Traces GT.M program execution and generates profiling information about the lines and functions executed; with low impact on the run-time performance.
The feature turns on (value=1) or turns off (value=0) tracing. <expr> must evaluate to a string containing the name of a GT.M global variable. The global may also have subscripts; however the subscripts must be literals or the special variable $JOB. Refer to the "Intrinsic Special Variable" chapter in this manual for process identifier description.
![[Note]](images/note.png)
|
|
|
The <expr> is optional when turning tracing off, if it exists, it overrides the global variable set when tracing was turned on. |
GT.M-tracing uses a technique called Basic Block Counting where calls are made to special profiling functions at key points in a GT.M program. A trace consists of the following run-time data as output for each GT.M function, as well as for each GT.M statement:
-
The number of times it is executed.
-
The total CPU time spent across all invocations for each function and each GT.M statement as a single value.
Instead of modifying the generated code as done by common profiling tools, such as gprof, GT.M tracing operates entirely within the GT.M run-time system; therefore, this feature does not require a special compilation, has no effect on code size and minimizes run-time overhead.
When the feature is turned on, it gathers profiling information for each line and GT.M function invocation. The reported time for a GT.M line is the time spent in generated code for that line, and does not include time spent in entreyrefs called from that line. When profiling is turned off, the accumulated statistics are loaded into a GT.M global. GT.M profiling accumulates and provides the data; the user may choose tools and techniques to analyze the data.
The trace information is stored in the variable in the following format:
-
If <expr> is a global variable without subscripts name such as "^foo", the trace information is stored in the nodes ^foo(<routine>,<label>) and ^foo(<routine>,<label>,<offset>), each of which has a value in the form "<count>:<time>" on VMS.
-
If <expr> has a value such as "^foo("MYTRACE",$J)", the trace information is stored in the nodes ^foo("MYTRACE",<pid>,<routine>,<label>) and ^foo("MYTRACE",<pid>,<routine>,<label>,<offset>), each of which has a value in the form "<count>,<time>" on VMS as described above.
-
For FOR loops, information for each level of the loop is stored in the nodes as described above, with the extra subscipts "FOR_LOOP". <for_level> is the value of the number of iterations at that level of the FOR loop.
Thus, if the GT.M program lv1.m is:
lv1f i=1:1:10 d
.s l(i)=i
.d bar
for i=1:1:5 for j=1:1:4 s lij(i,j)=i+j
q
bars l(-i)=-i
q
And the program lv2.m is:
lv2VIEW "TRACE":1:"^lvtr"
d ^lv1
VIEW "TRACE":0:"^lvtr"
zwr ^lvtr
q
On executing lv2, the output looks like this (times in the example were chose for clarity of illustration and are not typical):
^lvtr("lv1","bar")="10:8"
^lvtr("lv1","bar",0)="10:5"
^lvtr("lv1","bar",1)="10:3"
^lvtr("lv1","lv1")="1:37"
^lvtr("lv1","lv1",0)="1:8"
^lvtr("lv1","lv1",0,"FOR_LOOP",1)=10
^lvtr("lv1","lv1",1)="10:3"
^lvtr("lv1","lv1",2)="10:19"
^lvtr("lv1","lv1",3)="1:15"
^lvtr("lv1","lv1",3,"FOR_LOOP",1)=5
^lvtr("lv1","lv1",3,"FOR_LOOP",2)=20
^lvtr("lv1","lv1",4)="1:0"
^lvtr("lv2","lv2",1)="1:47"
In this case, ^lvtr("lv1","bar",0)="10:5" means that the statement bar s l(-i)=-i was executed 10 times, with a total of 5 microseconds of time. ^lvtr("lv1","lv1")="1:37" means that 37 microseconds of user time was spent within that GT.M frame (lv1^lv1), and does not include time spent in routines called from it (such as bar^lv1), whereas ^lvtr("lv1","lv1",3)= "1:15" includes the time spent at bar^lv1.
Note that there is no data in ^lvtr("lv2","lv2",0) or for ^lvtr("lv2","lv2",2) because the execution of the lines containing the VIEW commands that turn profiling on and off are not profiled.
Because of the underlying timers provided by the operating systems, times of less than a microsecond are measured as zero. Therefore, even if a statement executes one million times, it may report zero time if it took less than a microsecond each time.
GT.M profiling cannot handle more than 1024 levels. If the GT.M code executed has more than 1024 levels, frame information cannot be recorded, and frame information upto the first point where this limit is reached is reported with a note (":INCOMPLETE DATA: MAXTRACELEVEL" ) appended to the data.