Tracing Procedures

This article is a follow up of tracing. Two procedures are discussed that show how to trace entering and leaving procedures, such that the reader knows:

  1. When the procedure was entered

  2. When the procedure was finished

  3. How long this took

  4. How much memory was used or freed during its execution.

These latter two purposes are achieved by comparing the state at the beginning and end of the procedure.

Running example

The running example is based on a transportation problem: Pellets of bottled water are to be shipped from bottling locations to distribution centers. This example is extended with some logging and can be downloaded here

How to use

Suppose you have a procedure to do some work, for instance as follows:

1Procedure pr_doSolve {
2    Body: {
3        solve mp_transport ;
4    }
5}

By adding a few lines, and declarations, the execution of the procedure is traced. The additions are marked in yellow below.

1Procedure pr_doSolve {
2    Body: {
3        pr_enter(sp_enterTime,p_enterMemoryInUse);
4        solve mp_transport ;
5        pr_leave(sp_enterTime,p_enterMemoryInUse);
6    }
7    StringParameter sp_enterTime;
8    Parameter p_enterMemoryInUse;
9}

Remarks:

  1. Line 3: At the start of a procedure, trace the entering of that procedure. The arguments are used to store the part of the state (memory in use, moment of execution) in local parameters.

  2. Line 5: At the end of the procedure, trace the leaving of that procedure. In addition, trace how much memory and time has been used.

  3. Line 7,8: Declaration of local parameters.

Tip

As you know, lines of text can be copied. But the AIMMS Developer lets you also copy declarations; just right click on a declaration, keep the right mouse pressed, and move to the target location and select Copy Identifier(s).

How it is implemented

 1Procedure pr_enter {
 2    Arguments: (sp_procEnterTimestamp,p_procEnterMemoryInUse,sp_procEnterContextMessage);
 3    Body: {
 4        sp_procEnterTimestamp := CurrentToString("%c%y-%m-%d %H:%M:%S:%t%TZ('UTC')");
 5        p_procEnterMemoryInUse := MemoryInUse();
 6        sp_node := formatString("%e",CallerNode(1));
 7        sp_fullMsg := formatString("Enter %s(%s) at %s [%.3n Mb] in use",
 8            sp_node, sp_procEnterContextMessage,
 9            MomentToString(
10                Format        :  "%c%y-%m-%d %H:%M:%S:%t%TZ(ep_traceTimezone)",
11                unit          :  [s],
12                ReferenceDate :  sp_procEnterTimestamp,
13                Elapsed       :  0[s]),
14            p_procEnterMemoryInUse );
15        pr_logMsg( sp_fullMsg );
16    }
17    StringParameter sp_procEnterTimestamp {
18        Property: InOut;
19    }
20    Parameter p_procEnterMemoryInUse {
21        Property: InOut;
22    }
23    StringParameter sp_procEnterContextMessage {
24        Property: Optional;
25        Comment: {
26            "If the traced procedure contains arguments,
27            you may want to summarize these arguments here."
28             }
29    StringParameter sp_node;
30    StringParameter sp_fullMsg;
31}

Remarks:

  1. Line 4: Timestamps are recorded in timezone UTC. This eases the measurement of duration, as the reference time argument in StringToMoment is assumed to be in timezone UTC, well, at least since AIMMS 4.76.

  2. Line 6: CallerNode(1) returns the procedure that called the currently running procedure.

  3. Line 9-13: Only when communicating the timestamps to the log file, the timezone of the timestamp is converted to the local timezone. See also the initialization of element parameter ep_traceTimezone

 1Procedure pr_leave {
 2    Arguments: (sp_procEnterTimestamp,p_procEnterMemoryInUse,sp_msg);
 3    Body: {
 4        sp_leavingTime := CurrentToString("%c%y-%m-%d %H:%M:%S:%t%TZ('UTC')");
 5        p_duration := StringToMoment(
 6            Format        :  "%c%y-%m-%d %H:%M:%S:%t%TZ('UTC')",
 7            Unit          :  [s],
 8            ReferenceDate :  sp_procEnterTimestamp,
 9            Timeslot      :  sp_leavingTime);
10        sp_node := formatString("%e",CallerNode(1));
11        p_leaveMemoryInUse := MemoryInUse();
12        sp_fullMsg :=
13            formatString( "Leave %s(%s) at %s [%.3n Mb] in use. ",
14                sp_node, sp_msg,
15                MomentToString(
16                    Format        :  "%c%y-%m-%d %H:%M:%S:%t%TZ(ep_traceTimezone)",
17                    unit          :  [s],
18                    ReferenceDate :  sp_leavingTime,
19                    Elapsed       :  0[s]),
20                p_leaveMemoryInUse ) +
21            formatString( "Duration is %.3n [seconds] and memory %s is %n Mb.",
22                p_duration,
23                if p_leaveMemoryInUse >= p_procEnterMemoryInUse then "increase" else "decrease" endif,
24                abs( p_leaveMemoryInUse - p_procEnterMemoryInUse ) );
25        pr_logMsg( sp_fullMsg );
26    }
27    Parameter p_procEnterMemoryInUse {
28        Property: Input;
29    }
30    StringParameter sp_procEnterTimestamp {
31        Property: Input;
32    }
33    StringParameter sp_leavingTime;
34    Parameter p_duration {
35        Unit: s;
36    }
37    Parameter p_leaveMemoryInUse;
38    StringParameter sp_msg {
39        Property: Optional;
40    }
41    StringParameter sp_node;
42    StringParameter sp_fullMsg;
43}

Remarks:

  1. Line 5-9: Computing the duration. Note that UTC timestamps are compared.

  2. Line 21: The format string to trace how much time and memory was used to execute the procedure.

How to integrate

The code explained and demoed above is contained in a separate section named: Logging. See Export code to another project for copying the code to your project.