Profiling COBOL programs
The isCOBOL Framework provides the ability to profile COBOL programs in order to identify which paragraphs or sections have used most of the CPU time.
Note that this feature is not supported for programs that were compiled with
-big or
-sysc options 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 processing.
Command example:
iscrun -J-javaagent:/opt/iscobol/lib/isprofiler.jar IO_PERFORMANCE |
The above command starts the IO_PERFORMANCE sample installed with isCOBOL (it is stored in the folder sample/io-performance of the isCOBOL SDK).
When the runtime session terminates, a similar output is generated:
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.
A row for each measured block of code (paragraph of a program) is provided.
Columns have the following meaning:
• self % is the ratio between the time spent by the block of code and the evaluated time.
• accum % is the sum between the current self% and the previous ones.
• seconds is the number of seconds spent by the block of code.
• count is the number of times the block of code was executed.
• program:paragraph is the name of the block of code.
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.
Good practice for an accurate profiling
It’s good practice to profile only back-end programs, if possible. Profiling an interactive program may produce an unreliable report as the time spent by the user while interacting with the program is taken into account as well by the isCOBOL profiler. If the COBOL application consists of a set of programs that manage the UI and a set of programs that perform processing, then you may consider to profile only the second set of programs.
This may not always be an option, in which case try to be as quick as possible while inputing data to the program.
In order to provide an example, we can use the isCOBOL Demo (isControlSet) installed with isCOBOL. When you click on the “Print” button, a sub program (PRINTPROG) is called to manage the print job. Assuming that we wish to profile the activity of PRINTPROG, we can start the isCOBOL Demo as follows:
iscrun -J-javaagent:/opt/iscobol/lib/isprofiler.jar=PRINTPROG ISCONTROLSET |
When the runtime session terminates, a similar output is generated:
elapsed time = 4.58 evaluated time = 3.45 overhead1=27; overhead2=42 -------+-------+---------+-----------+----------------- self % |accum %| seconds | count |program:paragraph -------+-------+---------+-----------+----------------- 70.97%| 70.97%| 2.45| 1|PRINTPROG:MAIN 20.03%| 91.00%| 0.69| 1|PRINTPROG:SET_ATTRIBUTE 4.89%| 95.89%| 0.16| 1|PRINTPROG:LOAD_FONT 2.26%| 98.16%| 0.07| 1|PRINTPROG:ST_ADDRESS 1.33%| 99.50%| 0.04| 1|PRINTPROG:LOAD_BMP 0.13%| 99.63%| 0.00| 1|PRINTPROG:ST_UNDER_LOGO 0.12%| 99.75%| 0.00| 18|PRINTPROG:RESET_COLUMN 0.10%| 99.85%| 0.00| 3|PRINTPROG:LOAD_LARGE_FONT2 0.05%| 99.91%| 0.00| 1|PRINTPROG:PRINT_F_PIC 0.04%| 99.96%| 0.00| 230|PRINTPROG:TEST_GIVING 0.02%| 99.98%| 0.00| 1|PRINTPROG:SMALL_FONT2 0.01%| 99.99%| 0.00| 1|PRINTPROG:LOAD_LARGE_FONT3 0.00%|100.00%| 0.00| 1|PRINTPROG:DESTROY_HANDLE |
There’s no trace of ISCONTROLSET in the profiler output. Only PRINTPROG has been profiled.
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 |
or
iscserver -J-javaagent:/opt/iscobol/lib/isprofiler.jar=PRINTPROG |
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.