Oracle BRM: PerfLib tool and why we need it?

Perflib "Quick Start" Guide

This guide is a brief introduction to how to install and setup Perflib to trace the BRM Connection Manager (CM) for those who would like to get started as soon as possible. This guide will only describe how to start the CM with Perflib enabled and collect trace data. 

Installing Perflib

Perflib is shipped in a single tar archive called something similar to perflib__REL_X_Y_Z__basic_license_linux6.tar.gz. The following installation steps will install Perflib:

1. cd $PIN_HOME
2. mkdir perflib
3. cd perflib
4. gunzip < perflib__REL_X_Y_Z__basic_license_linux6.tar.gz
5. cd install

Check Perflib Configuration

The default settings for Perflib are generally sufficient for basic application tracing and can be left unchanged. The configuration is defined via environment variables defined in the perf.env file, with each parameter being documented (at least at high-level). Please feel free to investigate alternative configuration options to see how things behave. Below are some parameters which it may be worth considering for modification.

Parameter Notes

PERFLIB_OPCODE_BUCKET_FILE 

The opcode bucket file allows histograms to be defined for specific opcodes (or all). This can be useful if a specific opcode is under investigation and it is suspected that the performance is sometimes poor, or at certain times degrades in performance. The use of histograms allows one to classify calls into buckets by execution time.

PERFLIB_AGGREGATION_PERIOD 

The aggregation period defines how Perflib will organize data into trace files. Organizing the trace data into well-defined periods allows correlation with other system data and reports (OS utilization reports, AWR reports etc.). The aggregation period may be every hour, every 15 minutes etc. Choose the level of granularity that is appropriate for your test cases.

PERFLIB_FLUSH_FREQUENCY 

This parameter defines how frequently each process will flush data to file. In general, when using the PERFLIB_AGGREGATION_PERIOD one does not need to flush data more frequently (as data is always flushed when an aggregation period terminates), but it can be helpful to get results sooner. Note that flushing more often will increase the size of trace files.

Starting the CM with Perflib

The Perflib only requires some environment variables to be set to allow it to function (in particular the LD_PRELOAD variable, which allows the

CM process to recognise the Perflib). To start the CM with the Perflib enabled:

Stop the CM process using the stop_cm script (or equivalent).

prompt> stop_cm

Start the CM using the start_it script provided with Perflib. The start_it script simply sets environment variables for Perflib prior to

executing the command provided. Typically the CM will be started using the start_cm script provided with BRM.

prompt> ./start_it start_cm

Enabling Tracing

The Perflib, by default, does not start tracing operations immediately (although this can be enabled, if desired - usually it is only necessary for

debugging performance issues in the CM startup process). Tracing of operations can be enabled and disabled at any time. A small control

program, pstatus, is provided to control Perflib behaviour (and may also be used to report execution in real-time, if enabled). The following steps

describe how tracing may be enabled.

When Perflib starts, it creates a memory-mapped data file perflib_data.dat (this is the default defined by the PERFLIB_DATA_FILE

parameter which can be modified if desired).

To enable tracing of the complete opcode hierarchy one may execute:

prompt> ./pstatus -t2 perflib_data.dat

prompt> ./pstatus perflib_data.dat

time=2

flist=0

alarm=0

The time parameter indicates that tracing has been enabled.

To test that tracing is working correctly, one my execute a simple testnap script as verification.

prompt> testnap

===> database 0.0.0.1 from pin.conf "userid"

nap(12562)> q

prompt> ls *.plog.txt

perf_log.12495.20131003_133000.20131003_140000.plog.txt

prompt>

When the testnap script ended, the CM child which was spawned will terminate, and Perflib will automatically flush trace data to file

(flushing occurs either when an aggregation period expires, a flush period expires, or a process terminates).

This test trace file can be removed... It is now possible to execute a test (e.g. execute pin_bill_accts).

Note that tracing can be disabled and enabled at any time without interrupting the test which is in progress. This can be useful to allow

tracing to be started after an application has warmed-upor to trace only for a short period. In general, for long running tests, one typically

leaves tracing enabled and uses the PERFLIB_AGGREGATION_PERIOD variable to control and organize trace data. To disable tracing,

simply use the pstatus command again:

prompt> ./pstatus -t0 perflib_data.dat

Linux Link Warnings

When starting Perflib in this way on Linux, you may see the following message printed a number of times on the terminal:

ERROR: ld.so: object '/home/pin/dev/perf/libperflib.so' from LD_PRELOAD cannot be preloaded:

ignored.

This is because of the way LD_PRELOAD is set by the start_it script and that fact that libperflib.so is a 32-bit library. As most

operating system commands are 64-bit, the attempt to preload a 32-bit library when these commands execute is logged as an

error. This in now way affects the behaviour of the CM or Perflib.

Real-Time Tracing

The Perflib also allows opcode calls to be recorded in real-time. Normally, one wishes to trace the entire opcode call stack and aggregate that

data over time (which is what happens when timing is set to 2 in Perflib). However, it can also be useful to see opcode statistics in real-time. This

can be done by setting the Perflib timing flag to 1 (real-time and batch tracing can be enabled at the same time by setting the timing to 3). The

real-time tracing flag can be enabled and disabled at any time using the pstatus application in the same way as described above for batch

tracing.

When tracing in real-time, no data is written to file, but opcode statistics are collected in the perflib_data.dat memory-mapped file. The pstatus c

ommand can be used to report that data.

For example, one may print out the ongoing opcode execution statistics every 5 seconds using:

prompt> ./pstatus -s5 -H -csncta perflib_data.dat

Timestamp Opcode Name Calls Elapsed

OpAvg

--------- ----------- ----- -------

-----

15/09/2016 03:24:47 PCM_OP_SEARCH 920 1.170395

0.001272

15/09/2016 03:24:47 PCM_OP_ACT_LOGIN 3 0.114105

0.038035

15/09/2016 03:24:47 PCM_OP_PERFLIB_GET_SNAPSHOT 5 0.092582

0.018516

Timestamp Opcode Name Calls Elapsed

OpAvg

--------- ----------- ----- -------

-----

15/09/2016 03:24:52 PCM_OP_SEARCH 928 1.179559

0.001271

15/09/2016 03:24:52 PCM_OP_ACT_LOGIN 3 0.114105

0.038035

15/09/2016 03:24:52 PCM_OP_PERFLIB_GET_SNAPSHOT 5 0.092582

0.018516

Timestamp Opcode Name Calls Elapsed

OpAvg

--------- ----------- ----- -------

-----

15/09/2016 03:24:57 PCM_OP_SEARCH 936 1.191375

0.001273

15/09/2016 03:24:57 PCM_OP_ACT_LOGIN 3 0.114105

0.038035

15/09/2016 03:24:57 PCM_OP_PERFLIB_GET_SNAPSHOT 8 0.182278

0.022785

Timestamp Opcode Name Calls Elapsed

OpAvg

--------- ----------- ----- -------

-----

15/09/2016 03:25:02 PCM_OP_SEARCH 944 1.203889

0.001275

15/09/2016 03:25:02 PCM_OP_ACT_LOGIN 3 0.114105

0.038035

15/09/2016 03:25:02 PCM_OP_PERFLIB_GET_SNAPSHOT 8 0.182278

0.022785

Timestamp Opcode Name Calls Elapsed

OpAvg

--------- ----------- ----- -------

-----

15/09/2016 03:25:07 PCM_OP_SEARCH 952 1.214613

0.001276

15/09/2016 03:25:07 PCM_OP_ACT_LOGIN 3 0.114105

0.038035

15/09/2016 03:25:07 PCM_OP_PERFLIB_GET_SNAPSHOT 8 0.182278

0.022785

This allows one to track the opcode calls as they happen, which can be useful to gauge the progress of particular tests. For more information on

the options available with the pstatus application, please execute ./pstatus -h for help.

Real-Time Tracing

Sharing Trace Data

Once testing is completed, the trace files (*.plog.txt) can be shared with us for analysis. If possible, AWR reports from the database for the same periods as the test and trace data should be provided.