Profiling COBOL programs

The isCOBOL Framework provides the ability to profile COBOL programs in order to identify which paragraphs or sections are used most of the CPU time during a elaboration.

Note that this feature is not supported for programs that were compiled with -big option and for CLASS-ID programs.

The following jar libraries, installed along with isCOBOL, are necessary in the Classpath:

•	isprofiler.jar

•	javassist.jar

In order to enable the profiling, add the following option to the runtime command-line:

-J-javaagent:[path/to/]isprofiler.jar[=list-of-programs]

Where:

•	[path/to/]isprofiler.jar is the name and path of the isprofiler library. If no path is specified, the library is searched in the current directory.

•

list-of-programs is a optional parameter. It is a comma-separated list of regular expressions defining the programs to profile. The default value is "[A-Z_][A-Z0-9_]*" (all the classes whose name is fully uppercase). This is useful to discard programs with user interface and focus the profiling on programs that perform back-end elaboration.

Command example:

iscrun -J-javaagent:/opt/iscobol/lib/isprofiler.jar=ELAB001,ELAB003 LOGIN

The above command starts the main program LOGIN and allows the user to work with the COBOL application. When ELAB001 and ELAB003 are executed during the runtime session, their activity is profiled.

When the runtime session terminates, a similar output is generated:

isCOBOL profile rev $Revision: 18624 $ created Thu Nov 26 17:52:19 CET 2015 elapsed time = 2.40 evaluated time = 2.19 overhead1=25; overhead2=35 -------+-------+---------+-----------+----------------- self % |accum %| seconds | count |program:paragraph -------+-------+---------+-----------+----------------- 29.38%| 29.38%| 0.64| 1|IO_INDEXED:DELETE_FILE1_TEST 14.98%| 44.37%| 0.32| 1|IO_INDEXED:UPDATE_FILE1_TEST 12.75%| 57.12%| 0.27| 1|IO_INDEXED:LOAD_FILE1_TEST 6.91%| 64.03%| 0.15| 1|IO_SEQUENTIAL:LOAD_FILE1_TEST 6.33%| 70.37%| 0.13| 1|IO_INDEXED:READ_FILE1_TEST 6.23%| 76.60%| 0.13| 1|IO_RELATIVE:UPDATE_FILE1_TEST 5.29%| 81.89%| 0.11| 1|IO_RELATIVE:DELETE_FILE1_TEST 4.17%| 86.06%| 0.09| 1|IO_SEQUENTIAL:READ_FILE1_TEST 3.79%| 89.86%| 0.08| 1|IO_RELATIVE:LOAD_FILE1_TEST 3.12%| 92.99%| 0.06| 1|IO_PERFORMANCE:MAIN_LOGIC 2.96%| 95.95%| 0.06| 1|IO_RELATIVE:READ_FILE1_TEST 1.97%| 97.92%| 0.04| 1|IO_INDEXED:MAIN_LOGIC 0.87%| 98.80%| 0.01| 4|IO_RELATIVE:START_TIMER 0.53%| 99.34%| 0.01| 4|IO_INDEXED:START_TIMER 0.49%| 99.83%| 0.01| 2|IO_SEQUENTIAL:START_TIMER 0.05%| 99.89%| 0.00| 1|IO_SEQUENTIAL:MAIN_LOGIC 0.05%| 99.95%| 0.00| 1|IO_RELATIVE:MAIN_LOGIC 0.03%| 99.98%| 0.00| 4|IO_INDEXED:STOP_TIMER 0.00%| 99.99%| 0.00| 4|IO_RELATIVE:STOP_TIMER 0.00%|100.00%| 0.00| 2|IO_SEQUENTIAL:STOP_TIMER

Note - The snippet above shows the profiling result of the IO_PERFORMANCE sample program using JIsam as file handler on a recent PC.

The output is stored in a file named iscobol.hprof.txt, generated in the working directory.

The information in the file header has the following meaning:

•	elapsed time is the real time passed between the profiler startup and the report generation.

•	evaluated time is time spent executing COBOL paragraphs.

•	overhead1 is the estimated overhead in nanoseconds added by the profiler for each paragraph not containing PERFORM/CALL.

•	overhead2 is the further estimated overhead in nanoseconds for each PERFORM/CALL.

The profile of a program execution is obtained by measuring the time spent in individual paragraph (excluding the time spent in PERFORM/CALL) and by counting the number of times each paragraph is called.

The profiler adds an overhead that is roughly the same for each paragraph. This overhead is evaluated before the profiling and it is subtracted from the results. However the estimated overhead and the actual overhead can differ from time to time due to the machine status (multitasking, JIT compiler, etc).

If a paragraph has very few statements and it is executed many more times that the other paragraphs, the difference may be relevant and may affect the results accordingly.

The profile will include a row for each instance. It means that if a program is called, cancelled then called again or if a program is called in thread, more instances of the same program will be profiled and it will appear multiple time in the profiler output.

Thin client:

In a thin client environment it is possible to profile the application server (isCOBOL Server) activity by starting the server process with the same -javaagent option used for the runtime. E.g.:

iscserver -J-javaagent:/opt/iscobol/lib/isprofiler.jar=ELAB001,ELAB003

The profiling output is shown when the whole application server is terminated and it includes the profiling of all clients activities mixed together, therefore, if you need to profile some programs in a thin client environment, you should use a dedicated application server with only one client connected.