Search                        Top                                  Index
HELP TRACE                                    Aaron Sloman, October 1981
                                     Updated John Williams, January 1988

         CONTENTS - (Use <ENTER> g to access required sections)

 -- Introduction
 -- Summary of basic tracing facilities
 -- trace <procedure names> ;
 -- Tracing a recursive procedure
 -- Tracing several procedures
 -- untrace <procedure names> ;
 -- Switching all tracing off or on
 -- Local tracing
 -- Re-defining traced procedures
 -- Tracing system procedures
 -- Tracing of updaters
 -- Display format for abnormal procedure entry/exit
 -- The current tracing level: poptraceindent
 -- Maximum number of ! to print: popmaxtraceindent
 -- Character consumer for trace printing: cuchartrace
 -- Summary of more advanced facilities
 -- systrace(PROC, NAME, TRACEPROC, UPDATER)
 -- systrace_proc(PROC, NAME, UPDATER)
 -- systrace_pr(NAME, STATUS, ARGS, UPDATER)


-- Introduction --------------------------------------------------------

This file describes the POP11 'trace' mechanism - a tool for monitoring
procedure execution. The facilities available include:

    Tracing named procedures
    Ceasing to trace (untracing) named procedures
    Switching all trace output on/off
    Re-directing trace output (eg to a disk file)
    Changing the format of trace output

Essentially, tracing a procedure involves modifying it so that
information about its arguments and results is printed whenever the
procedure is invoked.

The first part of this file explains the simple default facilities
provided by the syntax words -trace- and -untrace-, and the variable
-tracing-. TEACH * TRACE goes into more detail on simple uses.

The second part describes the tracing mechanism in more detail, and
explains how users can adapt it for their own use.

The provision of "active variables" in POPLOG Version 13 implies that
new tracing facilities for variables could be provided. When that
happens this file will be updated.


-- Summary of basic tracing facilities ---------------------------------

trace <names of procedures> ;
    Enables tracing of the named procedures.

untrace <names of procedures>;
    Disables tracing of the named procedures.

<true|false|1> -> tracing;
    Resumes/Suspends trace printing of all traced procedures.
    Assigning 1 to -tracing- enables tracing of syntax procedures

untrace;
    Suspends trace printing for all traced procedures
    (Equivalent to:  'false -> tracing;')

trace;
    Resumes trace printing for all traced procedures
    (Equivalent to:  'true -> tracing;')

untraceall;
    Untraces all currently traced procedures.


The procedure names specified in the -trace- and -untrace- syntax forms
may be optionally separated by commas.


-- trace <procedure names> ; -------------------------------------------

This syntax word alters procedures so that they print out information
whenever they are executed. Tracing a procedure changes it so that when
called, it does "before" printing, then it runs, then it does "after"
printing.

The "before" printing includes the name of the procedure and the inputs
(arguments) to the procedure (if any). "After" printing includes the
results of the procedure (if any). Both "before" and "after" printing
indicate the total depth of currently active traced procedure calls by
printing a row of `!` characters, followed by `>` before, and `<` after
the procedure has run.

So, a call to a traced procedure -foo-, that takes three arguments and
produces two results, might look like

    !!!> foo arg1 arg2 arg3
    !!!< foo result1 result2

The three `!` characters indicate that there were three other traced
procedures active (present in the call stack) when -foo- was called.


-- Tracing a recursive procedure ---------------------------------------

Tracing is a useful way of displaying intermediate arguments and
results. An example follows.

    define addup(num);
        lvars num;
        if num == 0 then
            0
        else
            num + addup(num - 1)
        endif
    enddefine;

    addup(3) =>
    ** 6

    trace addup;

This causes nothing to be printed out - it merely changes the procedure
-addup- so that IT does the printing when run, e.g.

    addup(3) =>
    > addup 3            ;;; entering addup(3)
    !> addup 2           ;;; entering addup(2)
    !!> addup 1
    !!!> addup 0         ;;; entering addup(0) - recursion terminates
    !!!< addup 0         ;;; leaving addup(0) with result 0
    !!< addup 1          ;;; leaving addup(1) with result 1
    !< addup 3           ;;; leaving addup(2) with result 3
    < addup 6            ;;; leaving addup(3) with result 6
    ** 6                 ;;; printed by =>

Notice how the characters `>` and `<` indicate the beginning and end
(respectively) of procedure execution. The number of `!` characters
indicates the recursion depth.

There is an alternative to the `!` method of indicating depth; see below
for more details.


-- Tracing several procedures -----------------------------------------

You can specify several procedures to be traced, as follows:

    trace proc1 proc2 proc3;

which causes the three named procedures to be altered so that thereafter
they will cause trace-printing to occur when they are used.

See TEACH * TRACE for examples involving several procedures.


-- untrace <procedure names> ; -----------------------------------------

To stop trace printing of one or more procedures, use -untrace-, e.g.

    untrace proc1 proc3;

which will set the two named procedures back to normal.


-- Switching all tracing off or on ------------------------------------

vars tracing;

This is a global variable, default value -true-, that can be made
-false- to switch off all trace printing of traced procedures. The use
of -trace- or -untrace- sets it -true- again.

If you have declared a variable of your own called "tracing", the
interaction may cause some odd behaviour.

You can switch off ALL trace printing by doing either

    untrace;

or

    false -> tracing;

Previously traced procedures remain 'marked' as traceable. You can
restart tracing of such procedures by doing either

    trace;

or

    true -> tracing;

These uses of -trace- and -untrace- without arguments have their effects
immediately, and so they are not suitable for use inside a procedure
definition. Instead use an assignment to -tracing-.

The command

    untraceall;

untraces all previously traced procedures.

All other uses of -trace- and -untrace- (i.e. with named procedures),
will set tracing ON.

If the value 1 (as opposed to -true-) is assigned to -tracing-, then in
addition to switching tracing on, it will also be possible to trace
syntax procedures like -if- or -until-. Otherwise, attempting to trace a
syntax procedure causes an error.


-- Local tracing ------------------------------------------------------

-trace- and -untrace- can be used locally within a procedure definition
to trace or untrace a procedure defined locally. This enables tracing to
be dependent on calling environment.

    define foo;
        dlocal addup;     ;;; make addup local
        trace addup;      ;;; tracing will occur only when foo is active
        ........
    enddefine;


-- Re-defining traced procedures --------------------------------------

Definitions of procedures that have been traced, or their updaters, can
be edited and recompiled. The new procedure, or the new updater, will be
traced if the original one was. So re-tracing is uncessary.


-- Tracing system procedures ------------------------------------------

System procedures, e.g. -hd- can be traced in the usual way:

    trace hd;

However, this will only be effective for calls of -hd- that are compiled
AFTER this use of -trace-. So re-compile if necessary. Traced system
identifiers are no longer protected against redefinition by the user.
(See HELP * SYSUNPROTECT, * SYSPROTECT)


-- Tracing of updaters ------------------------------------------------

If a traced procedure has an updater, the updater will automatically be
traced. The trace printing will then include "updater" before the name.

For example:
    trace hd tl;
    vars list = [a b c d e];
    "C" -> hd(tl(tl(list)));
    > tl [a b c d e]             ;;; entering innermost call of tl
    < tl [b c d e]               ;;; leaving tl
    > tl [b c d e]               ;;; entering outer call of tl
    < tl [c d e]                 ;;; leaving tl
    > updater hd C [c d e]       ;;; entering updater of hd
    < updater hd                 ;;; finished

    list =>
    ** [a b C d e]


-- Display format for abnormal procedure entry/exit --------------------

From POPLOG Version 13.2, trace output is printed even if the procedure
is entered or exitted in an 'abnormal' fashion. This applies in three
circumstances: procedure entry due to process resumption, procedure exit
due to process suspension, and procedure exit due to -chain- or one of
its variants.

These abnormal entry/exit statuses are indicated by replacing the `>`
and `<` that occur in normal trace output by one of the following
characters:

    R       entry due to process resume
    S       exit due to process suspend
    X       any other abnormal exit

Exits due to -setpop- resetting the control stack are not displayed.

Display of type `X` procedure exits can be suppressed by doing

    false -> pop_chain_trace;

To suppress printing during type `S` and `R` procedure entry/exit, do

    false -> pop_process_trace;


Here is an example:

    define savechars();
        lvars count nchars;
        0 -> count;
        repeat
            -> nchars;
            if nchars == 0 then
                ksuspend(consstring(count), 1)
            else
                count + nchars -> count;
                suspend(count, 1)
            endif
        endrepeat
    enddefine;

The procedure -savechars- stores up characters on a process' user stack,
creating a string when no more characters are available. Each time
-savechars- is invoked, it is passed some characters, and an integer
indicating how many. If this integer is not 0, the characters are
stored, and the current total of saved characters is returned as the
process is suspended. If -savechars- is invoked with 0 characters, the
saved ones are made into a string which is returned as the process is
killed.

    vars p;
    trace runproc savechars;
    consproc(0, savechars) -> p;

    runproc(`e`, 1, 2, p) =>
    > runproc 2 <process>
    !> savechars            ;;; -savechars- entered for first time
    !S savechars            ;;; -savechars- suspended (1 is passed back)
    < runproc
    ** 1
    runproc(`x`, `i`, 2, 3, p) =>
    > runproc 3 <process>
    !R savechars            ;;; -savechars- resumed (with chars `x`,'i')
    !S savechars            ;;; -savechars- suspends; (-count- is now 3)
    < runproc
    ** 3
    runproc(`t`, 1, 2, p) =>
    > runproc 2 <process>
    !R savechars            ;;; -savechars- resumed (with char `t`)
    !S savechars            ;;; -savechars- suspends; (-count- is now 4)
    < runproc
    ** 4
    runproc(0, 1, p) =>
    > runproc 1 <process>
    !R savechars            ;;; -savechars- resumed (ith 0 chars)
    !X savechars            ;;; process is ksuspended (with 1 result)
    < runproc
    ** exit                 ;;; final string is printed


Note: abnormal exits of type `X` are not detectable if a procedure
simply exits from itself, for reasons too complicated to explain here.


-- The current tracing level: poptraceindent --------------------------

vars poptraceindent;

This global variable, initially 0, is incremented, in -systrace- (see
below) whenever a traced procedure is running. Declared local in
-systrace-, it is used by -systrace_pr- to count the number of `!`
characters to print.


-- Maximum number of ! to print: popmaxtraceindent ---------------------

vars popmaxtraceindent;

This global variable controls how recursion depth is displayed in trace
printing. When -poptraceindent- is less than -popmaxtraceindent-, depth
is indicated by a sequence of `!` characters, e.g.

    !!!!!> foo 1 2 3

If -poptraceindent- exceeds -popmaxtraceindent-, then the depth is
printed as an integer surrounded by square brackets, e.g.

    [  67]> foo

If you would prefer the latter format at all times, do

    0 -> popmaxtraceindent;

Then the call to -addup- used as an example above would produce this
output:

    addup(3) =>
    [   1]> addup 3
    [   2]> addup 2
    [   3]> addup 1
    [   4]> addup 0
    [   4]< addup 0
    [   3]< addup 1
    [   2]< addup 3
    [   1]< addup 6
    ** 6

The default value for -popmaxtraceindent- is 40.


-- Character consumer for trace printing: cuchartrace -----------------

vars cuchartrace;

The default value of this global variable is -false-. However, if it has
a character consumer procedure as its value, then this value is locally
assigned to -cucharout- by -systrace_pr- while trace information is
printed. Other printing (e.g. by the traced procedure itself) is
unaffected. This facility makes it possible to redirect trace output to
a disk file, or a special window (if running under a window manager).


-- Summary of more advanced facilities --------------------------------

The rest of this file describes the three procedures -systrace-,
-systrace_proc-, and -systrace_pr-, which together constitute the
tracing mechanism. The latter two are user-assignable, making it
possible to change both the basic function and display format of traced
procedures.


-- systrace(PROC, NAME, TRACEPROC, UPDATER) ----------------------------

This is the basic procedure. When a procedure is traced, the value of
the name given to -trace- is replaced by a closure of -systrace-,
partially applied to four arguments:

    PROC        The original procedure to be traced
    NAME        Its name
    TRACEPROC   Usually the word "systrace_proc"
    UPDATER     -true- if PROC is an updater, -false- otherwise

So, the command

    trace foo;

is roughly equivalent to

    systrace(%foo, "foo", "systrace_proc", false%) -> foo;
    "foo" ->> pdprops(foo) -> pdprops(updater(foo));

The procedure -systrace- is defined something like this:

    define systrace(Proc, Name, Traceproc, Upd);
        lvars Name Proc Traceproc Upd;
        dlocal poptraceindent;
        if tracing then
            poptraceindent + 1 -> poptraceindent;
            recursive_valof(Traceproc)(Proc, Name, Upd)
        else
            chain(Proc)
        endif
    enddefine;

If a procedure to be traced has an updater, then -trace- will make a
closure of -systrace- to replace the procedure, and assign a closure of
its updater to be its new updater. The updater of -systrace- takes the
same arguments as -systrace-, and simply does

        systrace(updater(Proc), Name, Traceproc, true)

So alterations to the original updater will affect tracing. The system
procedures -sysPASSIGN- and -sysUPASSIGN- (see REF * VMCODE) that handle
redefined procedures or their updaters, know how to deal with closures
of systrace so that redefining a traced procedure or its updater has the
expected effect.

The identifier -systrace- is NOT re-definable.


-- systrace_proc(PROC, NAME, UPDATER) ---------------------------------

The word "systrace_proc" is the third argument of -systrace-. Its value,
the procedure -systrace_proc-, does the actual trace printing and
running of the procedure. It takes three arguments:

    PROC        The original procedure to be traced
    NAME        Its name
    UPDATER     -true- if PROC is an updater, -false- otherwise

A simplified version of this procedure is:

    define systrace_proc(Proc, Name, Updater);
        lvars args Proc Name Updater n;
        consvector(pdnargs(Proc)) -> args;
        stacklength() -> n;
        systrace_pr(Name, `>`, args, Updater);
        explode(args);
        Proc();
        consvector(stacklength() - n) -> args;
        systrace_pr(Name, `<`, args, Updater);
        explode(args);
    enddefine;

I.e. it collects the arguments in a vector, calls -systrace_pr- to do
the trace entry printing, puts the arguments back on the stack, and
calls the traced procedure. Then it collects the results of the call
into a vector, calls -systrace_pr- to do the trace exit printing, and
finally puts the results back on the stack.

In fact, -systrace_proc- is considerably more complex than this. It
checks that the procedure has been supplied enough arguments (by
comparing the initial stack length with the procedure's -pdnargs-); it
also has to be careful of procedures like -erasenum- that decrease,
rather than increase, the number of items on the stack. Also,
-systrace_proc- includes a complicated 'dlocal expression' (see HELP *
DLOCAL) responsible for trapping abnormal exits from the traced
procedure.

-systrace_proc- may be re-defined by the user. This makes it possible
to completely change the behaviour of traced procedures. For example,
one might want to record or display execution times, or count the
number of times a procedure is called, or save the arguments and results
passed to/from a procedure for use during a debugging break.


-- systrace_pr(NAME, STATUS, ARGS, UPDATER) ----------------------------

This procedure is called by -systrace_proc- to do the actual printing of
trace information. It is passed four arguments:

    NAME        Name of the procedure being traced
    STATUS      An item indicating the entry/exit status of the
                procedure being traced (more details below).
    ARGS        A vector or list of arguments or results from the stack.
    UPDATER     -true- if an updater is being traced, -false- otherwise.

The entry/exit status codes currently defined are:

    -true-      normal entry
    -false-     normal exit
    `>`         normal entry
    `<`         normal exit
    `X`         abnormal exit
    `R`         re-entry due to process resume
    `S`         exit due to process suspend

-systrace_pr- is defined something like this:

    define systrace_pr(Name, Status, Args, Upd);
        lvars Name, Status, Args, Upd;
        dlocal cucharout = cuchartrace, tracing = false;
        repeat poptraceindent - 1 times cucharout(`!`) endrepeat;
        cucharout(Status);
        cucharout(`\s`);
        if Upd then spr("updater") endif;
        spr(Name);
        appdata(Args, spr);
        cucharout(`\n`)
    enddefine;

If -poptraceindent- exceeds -popmaxtraceindent-, then instead of
printing a series of `!`, the recursion depth is printed by

        cucharout(`[`);
        pr_field(poptraceindent, 4, `\s`, false, sys_syspr);
        cucharout(`]`);

-systrace_pr-, like -systrace_proc-, can be re-defined by the user.
This allows users to change the way trace information is printed. If you
want to modify tracing in more drastic ways, it is better to re-define
-systrace_proc- (see above).


--- C.all/help/trace ---------------------------------------------------
--- Copyright University of Sussex 1988. All rights reserved. ----------