Report: ProTop Execution Profiler Report

lib/zprofiler.p is also provided as an example for customers — it
shows how to instrument their own ABL code to take advantage of the
OpenEdge profiler from inside a running session. The
procedure myProfiler: block at the bottom of the source file is the
canonical pattern to copy into a customer application.

The basename (protop3 in the example) is whatever was passed in as the
first parameter when lib/zprofiler.p was launched; the .<yyyy>...<ss>
suffix is the launch timestamp, formatted in zprofiler_on. One report
is written per profiling session.

The output .rpt is placed in ./rpt/ if that directory exists relative
to the working directory; otherwise it goes to the current directory.
The raw profiler data (.prf) lands in session:temp-directory under
the same basename.

How a profile run is built

lib/zprofiler.p is not a one-shot program. It installs itself as a
session super-procedure ({lib/justone.i}) and exposes five internal
procedures that the calling code drives in sequence. The example block
at the end of the source file (procedure myProfiler:) shows the
canonical usage; ProTop’s interactive profile toggle wires up to that
pattern.

The lifecycle:

run lib/zprofiler.p persistent ( <basename>, <description> ) —
loads the PP, attaches it as a super-procedure, and stashes
<description> for later.
zprofiler_on — builds the timestamped output filename, sets
profiler:description / file-name / enabled / profiling, and starts
collecting. The .prf file lives at
<session:temp-directory><basename>.<yyyy>.<mm>.<dd>.<hh>.<mm>.<ss>.prf.
(Note: the order enabled = yes then profiling = yes matters — the
order in KBase P93997 is documented as wrong in the source comments.)
zprofiler_off — stops profiling and writes the .prf to disk
by setting profiler:enabled = no (which triggers write-data()
internally — calling write-data() explicitly and setting
enabled = no results in an empty file because the second write
overwrites the first).
zprofiler_load — reads the .prf into four temp-tables:
tt_profile (one row per profiling session in the file),
tt_source (one row per program/class id), tt_tree (caller→callee
tree, currently loaded then immediately deleted), and tt_ptime
(per-line execution counts and timings).
zprofiler_proc — collapses the per-session timings into
tt_code_line (one row per (program, line) pair across all
sessions), then walks every tt_source.pname looking for a matching
*.dbg file (a debug-listing produced at compile time with
compile ... debug-list) and stuffs the source-line text into
tt_code_line.src_line_txt. Programs whose name begins with
lib/zprofiler/ are filtered out so the profiler doesn’t profile
itself.
zprofiler_topx ( toTTY ) — emits the actual .rpt (or, if
toTTY = yes, draws the same content as a centered TTY frame).

Layout of the `.rpt`

Two stacked frames, written without further headers:

                            Profiler: Top 20 Results 
     Description: <profilerDescription> [<elapsed>]
     Session Total Execution Time   <hh:mm:ss>
     Line 0 = initialization, line -1 = cleanup

                       Top 20 Lines: Total Execution Time 
Program/Class                   Line          Time      Avg Time      Calls IP/Method            Code
------------------------------ ----- ------------- ------------- ---------- -------------------- --------------------------------------------------
<row 1>
...
<row 20>

Header frame (`prof-hdr`)

Description — the <description> argument, with [hh:mm:ss]
appended in zprofiler_off showing wall-clock elapsed between
zprofiler_on and zprofiler_off (i.e. how long the profiler was
running, not the cumulative work time).
Session Total Execution Time — sum of tt_code_line.t1 across
every row whose pname <> "session", formatted as hh:mm:ss. This is
cumulative CPU time as measured by the profiler.
Line 0 / -1 legend — line 0 rows are program initialization
(the implicit work that runs before the first executable line) and
line -1 rows are cleanup (post-return / destructor work). Both are
normal entries in profiler output and not bugs.

Body frame (`prof-rpt`) — Top 20 by Time

Rows are tt_code_line ordered by t1 descending (total execution
time). Rows whose pname = "session" are skipped. Only the top 20 are
printed.

Columns:

Program/Class — tt_code_line.pname, the .p / .cls source
file. If the original tt_source.pname had two space-separated
entries (typical for class methods), the second entry is the program
name and the first is split off into ipname (see below).
Line — tt_code_line.src_line, the source line number reported by
the profiler. 0 = initialization, -1 = cleanup.
Time — tt_code_line.t1, total execution time in seconds (sum of
tt_ptime.exe_time across all sessions for this (program, line)).
This is the sort key.
Avg Time — tt_code_line.t4 = t1 / t2, average seconds per call.
Calls — tt_code_line.t2, total invocations (sum of
tt_ptime.exec_count).
IP/Method — tt_code_line.ipname, the internal-procedure or
method name when one was carried in tt_source.pname (it shows up
as the second column in the second sample, e.g. mon-update,
gridRowDisplay, getColorNum).
Code — tt_code_line.src_line_txt, the actual source text for
that line, truncated to 50 chars. Only populated when a .dbg
file exists alongside the source (i.e. the program was compiled
with debug-list); otherwise the column is blank, as in the
earliest sample reports.

Side effects

Writes the .prf file under session:temp-directory. That file is
the raw profiler data and is not deleted by lib/zprofiler.p.
Writes the .rpt under ./rpt/ (preferred) or the current working
directory.
When zprofiler_topx is called with toTTY = yes, the same content
is drawn into centered overlay frames (prof-hdr, prof-rpt) and
the user is paused for input.
Does not call lib/uploader.p or lib/fileviewer.p; profiler
reports are intended for the local developer/DBA to read directly,
not to be shipped off.

Caveats

OpenEdge 12.2.3 is broken for this workflow: the profiler
produces empty data files. Upgrade to 12.2.4 or later. The source
comment cites
https://knowledgebase.progress.com/articles/Knowledge/profiler-system-handle-write-data-does-not-write-any-output/.
The Code column will be blank unless the profiled programs were
compiled with compile ... debug-list <file>.dbg. The processing
step looks up <programname-without-.p>.dbg next to each source
file via file-info:full-pathname; if that file isn’t found, the
source-line text is left blank for every row from that program. The
oldest sample reports in rpt/ show this state — the columns line
up but the right-most one is empty.
Programs whose source name begins with lib/zprofiler/ are filtered
out of the report so the profiler infrastructure doesn’t dominate
its own output. The session pseudo-program (pname = "session") is
also excluded from both the Top 20 list and the Session Total.

Reading the report

The Time column is the headline — it’s the sort key, so the
hottest line in the session is row 1. Anything spending serious
cumulative time at the top of the list is a candidate for
optimization.
A row with Line = 0 for a program means a lot of time was spent
in that program’s initialization (variable definitions, top-level
startup code that runs before the first procedure call). Programs
with high Line 0 time but low Time elsewhere are usually paying
startup costs disproportionate to their work.
High Avg Time + low Calls = an expensive but rare line; high
Calls + low Avg Time = a cheap line called in a tight loop —
the canonical profiler hot-spot.
The [hh:mm:ss] in the description is wall-clock elapsed; if it’s
far larger than the Session Total Execution Time the profiled
session was mostly idle (waiting on I/O, the user, or the DB). If
it’s close, the session was CPU-bound.
Compare runs by sorting rpt/ by filename — the timestamp in the
basename gives a natural chronological order. Diffing two runs of
the same scenario quickly highlights regressions.