Chapter 5. TRACE command and TRACE() function.

Types of tracing

A REXX procedure can be traced in single-step mode (called interactive trace) or in continuous mode.  In the first case, the user is able to interact with the procedure before or after the execution of each separate statement. 

REXX tracing can be enabled or disabled

  1. from outside the procedure via CMS immediate commands TS (Trace Start) and TE (Trace End) or via the SET EXECTRAC CMS command
  2. from inside the procedure through the REXX TRACE statement or TRACE() function.

TRACE (both statement and function) are normal REXX instructions, so there's nothing that prevents you to make tracing conditional via an IF statement.


Command reference.

This is the format of the TRACE command as explained in the manual and online HELP.

 ++--TRACE--+-+--------+---------------------+-----------------+
            ! +-number-+                     !
            !   +-------+                    !
            !   v       !  +-Normal--------+ !
            +----+---+--+--+---------------+-+
                 !-?-!     !-All-----------!
                 +-!-+     !-Commands------!
                           !-Error---------!
                           !-Failure-------!
                           !-Intermediates-!
                           !-Labels--------!
                           !-Off-----------!
                           !-Results-------!
                           +-Scan----------+
 Or, alternatively:
 ++--TRACE--+-----------------------+--------------------------+
            !-string----------------!
            !-symbol----------------!
            +-+-------+--expression-+
              +-VALUE-+

The notation used in the command format (they call it Railroad Tracks) are conform to the SAA architecture.  This format is used in most reference manuals nowadays.  If you don't know the rules for this kind of notation, please refer to Appendix B. Syntax diagrams..

TRACE is primarily used for debugging.  It controls the tracing action taken (that is, how much is displayed to the user) during execution of a REXX program.  The syntax of TRACE is more concise than that of other REXX instructions.  The economy of key strokes for this instruction is especially convenient since TRACE is often entered manually during interactive debugging. 

If specified, a number must be a whole number. 

The string or expression evaluates to :

The symbol is taken as a constant, and is, therefore :

The option that follows TRACE or the result of evaluating expression determines the tracing action.  If expression is used, you can omit the sub-keyword VALUE as long as expression starts with a special character or operator (so it is not mistaken for a symbol or string).

The TRACE() function

The format is simple:

 ++--TRACE(--+--------+--)---------------------------------------+
             +-option-+

The function returns trace actions currently in effect.

If an option is supplied, it must be one of the valid prefixes "?" or "!" and/or one of the alphabetic character options (that is, starting with "A", "C", "E", "F", "I", "L", "N", "O", "R", or "S") associated with the TRACE instruction. 

The function uses the option to alter the effective trace action (such as tracing Labels, and so forth). 

Unlike the TRACE instruction, the TRACE() function alters the trace action even if interactive debug is active

Also unlike the TRACE instruction, option cannot be a number. 

Format of TRACE Output

Every clause traced is displayed with automatic formatting (indentation) according to its logical depth of nesting and so forth.  The language processor may replace any control codes in the encoding of data (for example, EBCDIC values less than '40'x or ASCII values less than '20'x) with a question mark (?) to avoid console interference.  Results (if requested) are indented an extra two spaces and are enclosed in double quotes so that leading and trailing blanks are apparent. 

The first clause traced on any line is preceded by its line number.  If the line number is greater than 99999, it is truncated on the left and a prefix of ? indicates the truncation.  For example, the line number 100354 is shown as ?00354.

All lines displayed during tracing have a three-character prefix to identify the type of data being traced.  These can be:
*-* Identifies the source of a single clause, that is, the data actually in the program.
+++ Identifies a trace message.  This may be the non zero return code from a command, the prompt message when interactive debug is entered, an indication of a syntax error when in interactive debug, or the trace back clauses after a syntax error in the program (see below).
>>> Identifies the result of an expression (for TRACE R) or the value assigned to a variable during parsing, or the value returned from a subroutine call.
>.> Identifies the value "assigned" to a place holder during parsing.

The following prefixes are only used if TRACE Intermediates is in effect :
>C> The data traced is the name of a compound variable, traced after substitution and before use, provided that the name had the value of a variable substituted into it.
>F> The data traced is the result of a function call.
>L> The data traced is a literal (string, uninitialized variable, or constant symbol).
>O> The data traced is the result of an operation on two terms.
>P> The data traced is the result of a prefix operation.
>V> The data traced is the contents of a variable.

Following a syntax error that SIGNAL ON SYNTAX does not trap, the clause in error is always traced.  Any CALL or INTERPRET or function invocation clauses active at the time of the error are also traced.  If an attempt to transfer control to a label that could not be found caused the error, that label is also traced.  The special trace prefix +++ identifies these trace back lines.


Scope of tracing.

Following rules apply to the scope of tracing in REXX procedures:

  1. When interactive tracing is enabled, all (subsequent) TRACE commands coded in the procedure are ignored.
  2. When interactive tracing is enabled, TRACE() functions are not ignored.  More about this later in the lesson. 
  3. Subroutines inherit the trace settings as set by the calling routine.
  4. If subroutines change the trace settings, then this is local to the subroutine and trace settings as defined by the caller are resumed when the subroutine returns.

Have a look at next procedure :

Scope of tracing

   /* Scope of tracing */
    address command
    trace ?r
    number_disks=sub1()
    say 'You have 'number_disks' disks or directories accessed'
    exit
    SUB1:
      say 'Now we run sub1'
      accnum=sub2()
      trace off
      say 'After sub2 ran'
    return accnum
    SUB2:
      say 'Now in sub2'
      'MAKEBUF'
      oldbuf=rc
      trc=trace('Off')
      oldentries=queued()
      'QUERY DISK (STACK'
      numacc=queued()-oldentries
      'DROPBUF' oldbuf
    return numacc

The trace ?r instruction at the beginning of the procedure starts interactive tracing.

When subroutine SUB1 starts execution, its first 2 statements get traced as SUB1 inherits the trace settings as defined by the main routine.

The trace off statement is traced also and results in no action (hence tracing is not turned off) as with interactive tracing TRACE commands are ignored, so, the rest of SUB1 gets traced too.

When subroutine SUB2 starts, interactive tracing continues for the first 3 statements, as SUB2 also inherits the settings from the previous routines.

The trc=trace('Off') statement effectively turns tracing off (we use the TRACE() function here, and this is not ignored).  Tracing remains off for the duration of SUB2, but is resumed when SUB1 gets control again as the scope of the trace() function is local to the subroutine. 

Note that if we had coded call trace off instead of trc=trace('Off'), the results would have been the same.

Question 11

Aren't you puzzled by this last remark ?  No, then you will be able to explain us why both ways of coding are equivalent.  Also, if you don't see why both variants can produce different results, you surely must read the answer text for question 11, and read that till the very last sentence.


Alphabetic Character Options for TRACE.

Overview.

TRACE actions correspond to the alphabetic character options as follows :

All All clauses are traced (that is, displayed) before execution.
Commands All commands are traced before execution, and any error return code is displayed.
Error Any command resulting in an error or failure is traced after execution, together with the return code from the command.
Failure Any command resulting in a negative return code is traced after execution.  This is the same as the Normal option.
Intermediates All clauses are traced before execution.  Intermediate results during evaluation of expressions and substituted names are also traced.
Labels Labels passed during execution are traced.  This is especially useful with debug mode, when the language processor pauses after each label.  It is also convenient for the user to make note of all subroutine calls and signals.
Normal (Normal or Negative); any command resulting in a negative return code is traced after execution.  This is the default setting.
Off Nothing is traced, and the special prefix actions (described later) are reset to OFF.
Results All clauses are traced before execution.  Final results (contrast with Intermediates, preceding) of evaluating an expression are traced.  Values assigned during PULL, ARG, and PARSE instructions are also displayed.  This setting is recommended for general debugging.
Scan All remaining clauses in the data are traced without being executed.  Basic checking (for missing ENDs and so forth) is carried out, and the trace is formatted as usual.  This is valid only if the TRACE S clause itself is not nested in any other instruction (including INTERPRET or interactive debug) or in an internal routine.

Although you can enter the word in full, only the capitalized letter is needed; all characters following it are ignored.  That is why these are referred to as alphabetic character options. 

When the manual says that statements are traced before execution, then it means this : the trace output is shown at the terminal, before the statement is actually executed.  So, the statement gets indeed executed before the next statement is interpreted, or, in the case of interactive tracing, before the terminal displays the VM READ state.

Trace options revisited by your instructors.

In most of the examples that follow, we use the procedure listed here.  It accepts a parameter by which we can choose the type of tracing we want to perform.
Trace Testing procedure.

/***********************************************************************/
/* Procedure TTEST                                                     */
/* Allows to verify the tracing results in REXX                        */
/***********************************************************************/
address command
parse upper arg traceopt
trace value(traceopt)
do i=1 to 4
   i=i+1
end
call subrout
exit
SUBROUT:
 say 'Value of i=' i
 return

Tracing Results

In this first example, we use trace results.  This is not an interactive trace, so the tracing goes uninterrupted until the procedure ends or cancels due to an error. 

» ttest r
     8 *-* do i=1 to 4
       >>>   "1"
       >>>   "4"
     9 *-*  i=i+1
       >>>    "2"
    10 *-* end
     8 *-* do i=1 to 4
     9 *-*  i=i+1
       >>>    "4"
    10 *-* end
     8 *-* do i=1 to 4
    11 *-* call subrout
    13 *-*  SUBROUT:
    14 *-*  say 'Value of i=' i
       >>>    "Value of i= 5"
Value of i= 5
    15 *-*  return
    12 *-* exit
Ready; T=0.01/0.02 11:43:46

What do we learn from this example ?

  1. We see that the do-statement at line 8 is repeated 3 times.  The last time, the condition is no longer true, so the loop is not performed a third time and REXX continues with statement 11 just after the do-block. 
  2. With Result tracing, REXX gives the resulting values of the variables in each statement.  So, when the loop is initiated, the trace indicates that the value of i must go from 1 to 4.  At statement 9, the value of i becomes 2.  As the do-loop also increments the variable i, the second time we execute statement 9 the value of i becomes 4 (+1 from the do and +1 from the addition in statement 9).

Tracing Intermediate results.

The procedure is now run with the parameter i, thus intermediate result tracing is activated.

» ttest i
     8 *-* do i=1 to 4
       >L>   "1"
       >L>   "4"
     9 *-*  i=i+1
       >V>    "1"
       >L>    "1"
       >O>    "2"
    10 *-* end
     8 *-* do i=1 to 4
     9 *-*  i=i+1
       >V>    "3"
       >L>    "1"
       >O>    "4"
    10 *-* end
     8 *-* do i=1 to 4
    11 *-* call subrout
    13 *-*  SUBROUT:
    14 *-*  say 'Value of i=' i
       >L>    "Value of i="
       >V>    "5"
       >O>    "Value of i= 5"
Value of i= 5
    15 *-*  return
    12 *-* exit
Ready; T=0.01/0.02 16:48:47

This time, the trace gives all intermediate values of all variables.  Let's analyze some steps in more detail:

Tracing Intermediate results is the most powerful tracing option as it shows the details on how REXX interprets the statements by displaying the intermediate results.

Tracing Labels.

If we just trace labels, then the output is like the one below.  Tracing labels can help you to understand the gross logic of the procedure, especially if you structure your procedure as we will discuss later.  It can also be handsome if you want to trace without details until you reach the subroutine you want to analyze in more detail.

» ttest label
    13 *-*  SUBROUT:
Value of i= 5
Ready; T=0.01/0.01 16:48:49

Tracing All.

Next example traces All statements.  You don't get the intermediate results, you just get the logic flow of the procedure.  This is handy if you have to find an error in the logic flow of your procedure. 

» ttest all
     8 *-* do i=1 to 4
     9 *-*  i=i+1
    10 *-* end
     8 *-* do i=1 to 4
     9 *-*  i=i+1
    10 *-* end
     8 *-* do i=1 to 4
    11 *-* call subrout
    13 *-*  SUBROUT:
    14 *-*  say 'Value of i=' i
Value of i= 5
    15 *-*  return
    12 *-* exit
Ready; T=0.01/0.02 16:48:59

Tracing with Scan option.

When TRACE SCAN is included in a procedure, it will not really be executed, but REXX will scan the whole file for basic syntax errors, such as:

A trace scan will however NOT find errors that depend on execution values.  So, it will not detect

For all larger procedures, perform a trace scan at least once.  As all subroutines will be scanned, errors may be revealed faster than making test runs to force your procedure to go through all subroutines.

These are the steps you should perform:

Cumbersome?  Yes indeed, therefore we have the CKRX goodie that performs this for you.  The result of the trace is saved in a file if problems are found.  EXECCALL and CKRX are available as part of the REXXG package on VM's download library.

Tracing with the Command option.

Trace Command is useful too as it limits the trace output.  When you trace a complete procedure, you probably do it because you know where things start to go the bad way.  With a TRACE C, you can step through the procedure until you get at the failing command, and then you can issue the TRACE R instruction to see what REXX really does.  Tricky errors are most of the time not in the commands themselves, but in the REXX statements near to the commands. 

Tracing with the Error option.

This option is not 100% useful these days, as for example:

  1. some commands return a non-zero return code, not to indicate an error, but to inform you about some status.  So for example,
  2. initialization routines will erase work files that will be reused in the procedure.  These file may or may not exist.  In the latter case, the ERASE command will issue a return code 28, but this may be totally acceptable in the situation just described.

A trace Error would in these cases show errors that aren't errors.

Normal, Negative or Failure Tracing.

The default for tracing is Normal (or some call it Negative).  Failure is another synonym. TRACE N is the best default.

Just to refresh your memory, CMS returns negative return codes to indicate
  • that a command is not recognized (RC=-3)
  • that a command can't be executed while in CMS Subset environment (RC=-2)
  • that a CP command is not recognized (RC=-1).  (The CP return code +1 is converted to a -1 by CMS for commands entered from the virtual console).
  • etc...

Don't code a TRACE Off at the beginning of your REXX procedures (this is a habit you may have taken over from EXEC 2 where you probably were used to the &TRACE OFF).

If you do, you overrule the default TRACE N, and the user will have fewer chances to see why a procedure cancels in case of unexpected - thus untested - errors.

For this same reason it is a bad habit to code too much SET CMSTYPE HT commands in your procedures.  Limit the use of this command to the cases where it is the only solution to suppress messages.  Remember that an address command already can suppress many messages.


Prefix Options for TRACE.

The trace command or function accepts also the prefixes ! and ?, with or without one of the alphabetic character options.  Both prefixes may even be specified together, in any order.  Each occurrence of a prefix reverses the action of the previous prefix.  The prefix(es) must immediately precede the option (no intervening blanks). 

The prefixes ! and ? modify tracing and execution as follows:
? Controls interactive debug.  During normal execution, a TRACE option prefixed with ? causes interactive debug to be switched on.  While interactive debug is on, interpretation pauses after most clauses that are traced.  For example, the instruction TRACE ?E makes the language processor pause for input after executing any command that returns an error (that is, a nonzero return code). 

Any TRACE instructions in the procedure being traced are ignored.  This is so that you are not taken out of interactive debug unexpectedly.

When interactive debug is in effect, you can switch it off by issuing a TRACE instruction with a prefix ?  Repeated use of the ? prefix, therefore, switches you alternately in and out of interactive debug.  Or, you can turn off interactive debug at any time by issuing TRACE O or TRACE with no options. 

Note: You can also enter interactive debug by entering the CMS immediate command TS from the command line.

! Is used to inhibit host command execution.  During normal execution, a TRACE instruction prefixed with ! causes execution of all subsequent host commands to be suspended.  For example, TRACE !C causes commands to be traced but not executed.  As each command is bypassed, the REXX special variable RC is set to 0.  This action may be used for debugging potentially destructive programs.  Note that this does not inhibit any commands issued manually while in interactive debug, these are always executed.

You can switch off command inhibition, when it is in effect, by issuing a TRACE instruction with a prefix !.  Repeated use of the ! prefix, therefore, switches you alternately in and out of command inhibition mode.  Or, you can turn off command inhibition at any time by issuing TRACE O or TRACE with no options.

Remember the 'NLS' differences with REXX.

In the USA character set, REXX uses:

  1. | (X'4F') as logical OR
  2. ! (X'5A') as prefix character for trace.

On Belgian terminals, X'4F' shows as !, and the prefix character for trace is X'5A', shown as ].  So, if you want to use the inhibit host commands prefix, you'll have to use an ] character instead of the ! as used in the manual and this document.

OS/2 has not the ! prefix option.

Inhibiting Host commands via '!' prefix.

Before we cover the ? prefix in more detail, we prefer to give our comments about the ! prefix first.

At first glance Inhibiting Host Commands via the ! prefix may seem very useful.  But we can not imagine many procedures that can run normally without executing the commands.

For example, next 2 frequently used statements will give a problem if the IDENTIFY instruction is not executed:

   'IDENTIFY (LIFO'   /* who are we .. */
   parse pull userid . nodeid . rscs .

If you inhibit the execution of the IDENTIFY command, then the parse pull statement will put you in an unexpected VM READ status.

At the opposite side of this, commands executed at second level, such as in

   Parse value diag(8,'Q USERID') with userid . nodeid . '15'X

are not recognized as host commands by REXX.  The Q USERID is executed as a result of the diag() function but is not inhibited by the ! trace prefix.  Indeed, diag() is a known REXX function and REXX is unaware that the diagnose code 8 results in the execution of a CP command. 

Remark also that the CP command in a diag() function is not traced when TRACE C is active !

There are other situations where REXX does NOT see the commands that are executed.  Without entering into details here, we mention the execution of commands through CSL calls (Callable Services).

The conclusion is that you can forget about the ! prefix for tracing.  It is better to use the simple technique explained below :

Prefix the command you don't want to execute yet with a say statement.  Once the procedure is fully tested you can remove those 'say' instructions.  To make life even easier, always 'disalign' the say statement and add a eye-catcher such as 'TEST'.  This way, an ALL /say 'TEST'/ will list all statements to be changed in one shot.

Inhibit host commands

 if ok then do              |  if ok then do
    file='ABS FILE A'       |     file='ABS FILE A'
    'ERASE' file            | Say 'TEST' 'ERASE' file
    ....                    |     ....
 end                        |  end
 else do                    |  else do
    ....                    |     ....
 end                        |  end

The advantage of using 'say' instructions instead of commenting out the command, is that it allows you to see if the syntax of the interpreted command is correct during the test of your procedure.  Furthermore, you will not forget as easily to eliminate the say instructions as the comments, and the 'disalignment' further help to ring a bell when you look back at the procedure. 

If you use the continuation character of REXX, then an even better coding style could be like this:

 if ok then do
    file='ABS FILE A'
 Say 'TEST',
    'ERASE' file
    ....
 end
 else do
    ....
 end

Now, a ALL /Say 'TEST',/#delete *#ALL XEDIT command will get rid of all those temporary say instructions in one shot, while we preserve the alignment of the real command statements.

You could even go one step further and include a TEST facility in your procedure.  You can leave it forever, and activate it by assigning a variable as in this example:

 test=1  /* set to 1 to test; to 0 for production */
 ...
 if ok then do
    file='ABS FILE A'
    cmd='ERASE' file
    if test then do; Say 'test:' cmd 'bypassed' ; rc=0 ; end
            else cmd
 end
 else do
    ....

Still better is a TEST parameter to be passed to the procedure.

We will now cover the ? prefix option, hence the interactive tracing in more detail in chapter 6.  But first answer this rehearsal question:

Question 12

Do you still remember what is the best TRACE option?  And why it is not TRACE OFF?


Footnotes:

  It is a pity that you have to modify the procedure as this, for example, will change the date.  TRACE S can't be entered during interactive trace.
Back to text