Introduction
Elastic COBOL Simple Profiler is an internal runtime facility that extends runtime tracing to emit "wall clock" execution timings.
Execution time tracing covers COBOL paragraphs/sections, calls, performs, gotos, and file i/o & SQL i/o operations.
The time reported is the time between the current trace message and the last trace message (within the same program).
Options
Time tracing is enabled with compiler directives. Tracing information can be controlled at runtime using environment variables.
These directives and other settings should be used in conjunction with those required for runtime tracing. By turning trace information on/off for each trace type, you can customize the timing information to, for example, report timings between each CALL statement.
Compiler directives:
- -run:tracetime -- activates time tracing for PARAGRAPH/SECTION, CALL, GOTO, PERFORM and FILE I/O & SQL I/O operations
- -run:notracetime (default) -- deactivates all time tracing information
Runtime settings (can be set in cblconfig and/or environment):
- RUN_TRACEFORMAT=DecimalFormat
Where DecimalFormat is the same as the Java specification:
http://docs.oracle.com/javase/tutorial/i18n/format/decimalFormat.html
Use Examples
$ ecobol -run:trace a.cbl bprog.cbl
$ ecobol -run:trace -run:tracetime a bprog
Elastic COBOL V14.12.16 Copyright (C) 2010-2014 Heirloom Computing
LOC: 38 (8 variables in 6 records)
Warnings: 0
Errors: 0
Result: Compilation SUCCESSFUL
Building: Class files
$ java a
TIME=[0000] PROG=[a] SECT=[A-SECTION] SOURCE=[a.cbl]
TIME=[0000] PROG=[a] PARA=[A-PARA OF A-SECTION] SOURCE=[a.cbl]
TIME=[0000] PROG=[a]*CALL=[C$SLEEP:literal] USING=["1.11"]
TIME=[0001] PROG=[a]*CALL=[bprog:literal] USING=["2.22","456","78.9"]
TIME=[0000] PROG=[bprog] SECT=[B-SECTION] SOURCE=[bprog.cbl]
TIME=[0000] PROG=[bprog] PARA=[B-PARA OF B-SECTION] SOURCE=[bprog.cbl]
TIME=[0000] PROG=[bprog]*CALL=[C$SLEEP:literal] USING=[lnk.a_item]
TIME=[0002] PROG=[bprog] PARA=[B-EXIT OF B-SECTION] SOURCE=[bprog.cbl]
TIME=[0002] PROG=[a]*PERF=[B-SECTION OF A-SECTION] SOURCE=[a.cbl]
TIME=[0000] PROG=[a] SECT=[B-SECTION] SOURCE=[a.cbl]
TIME=[0000] PROG=[a] PARA=[B-PARA OF B-SECTION] SOURCE=[a.cbl]
TIME=[0000] PROG=[a]*CALL=[C$SLEEP:literal] USING=["3.33"]
TIME=[0003] PROG=[a] PARA=[FINISH OF B-SECTION] SOURCE=[a.cbl]
TIME=[0000] PROG=[a]*GOTO=[FINISH OF A-SECTION] SOURCE=[a.cbl]
TIME=[0000] PROG=[a] PARA=[FINISH OF B-SECTION] SOURCE=[a.cbl]
$ export RUN_TRACEPARA=0
$ java a
TIME=[0000] PROG=[a]*CALL=[C$SLEEP:literal] USING=["1.11"]
TIME=[0001] PROG=[a]*CALL=[bprog:literal] USING=["2.22","456","78.9"]
TIME=[0000] PROG=[bprog]*CALL=[C$SLEEP:literal] USING=[lnk.a_item]
TIME=[0002] PROG=[a]*PERF=[B-SECTION OF A-SECTION] SOURCE=[a.cbl]
TIME=[0000] PROG=[a]*CALL=[C$SLEEP:literal] USING=["3.33"]
TIME=[0003] PROG=[a]*GOTO=[FINISH OF A-SECTION] SOURCE=[a.cbl]
$ export RUN_TRACEFORMAT="#0.000"
$ java a
TIME=[0.047] PROG=[a]*CALL=[C$SLEEP:literal] USING=["1.11"]
TIME=[1.123] PROG=[a]*CALL=[bprog:literal] USING=["2.22","456","78.9"]
TIME=[0.000] PROG=[bprog]*CALL=[C$SLEEP:literal] USING=[lnk.a_item]
TIME=[2.016] PROG=[a]*PERF=[B-SECTION OF A-SECTION] SOURCE=[a.cbl]
TIME=[0.000] PROG=[a]*CALL=[C$SLEEP:literal] USING=["3.33"]
TIME=[3.339] PROG=[a]*GOTO=[FINISH OF A-SECTION] SOURCE=[a.cbl]
$ export RUN_TRACETIME=0
$ java a
PROG=[a]*CALL=[C$SLEEP:literal] USING=["1.11"]
PROG=[a]*CALL=[bprog:literal] USING=["2.22","456","78.9"]
PROG=[bprog]*CALL=[C$SLEEP:literal] USING=[lnk.a_item]
PROG=[a]*PERF=[B-SECTION OF A-SECTION] SOURCE=[a.cbl]
PROG=[a]*CALL=[C$SLEEP:literal] USING=["3.33"]
PROG=[a]*GOTO=[FINISH OF A-SECTION] SOURCE=[a.cbl]
$ export RUN_TRACE=0
$ java a
[no output -- RUN_TRACE overrides all other settings]
0 Comments