15.4.3.1. Employing Normal TRACE for Debugging

This example creates multithreaded parts using the REPLY keyword instruction. To introduce some entropy the RANDOM() built-in function (BIF) gets used for generating a random sleep time. The resulting trace output will not have any multithreading related information such that it becomes impossible to realize which statements get executed on which thread.

Example 15.2. Employing Normal (Default) TRACE

.test~new~show  -- create instance & send it the "show" message

::class test

::method init     class -- class constructor
  expose counter        -- access class attribute "counter"
  counter=0             -- initialize to 0
::method nextNr   class -- class method
  expose counter        -- access class attribute "counter"
  counter+=1            -- increase counter
  return counter        -- return new value

::method init           -- instance constructor
  expose nr             -- access instance attribute "nr"
  nr=self~class~nextNr  -- get & assign next serial number
::method show           -- instance method
  expose nr             -- access instance attribute "nr"
  say "in" .context~name", before reply, nr="nr
  trace results         -- trace results
  reply                 -- return & execute rest on new thread
  sleepTime=random(1,750)/1000   -- get random sleep time
  call sysSleep sleepTime  -- sleep
  say self": I got created as:" pp("#" nr)

::routine pp      -- "pretty print": enquote argument in brackets
  trace results         -- will turn on invocation entry/exit
  return "[" || arg(1) || "]"

Running the above program may yield an output like:

in SHOW, before reply, nr=1
    22 *-* reply                 -- return & execute rest on new thread
in SHOW, before reply, nr=2
    22 *-* reply                 -- return & execute rest on new thread
    23 *-* sleepTime=random(1,750)/1000   -- get random sleep time
       >>>   "0.654"
in SHOW, before reply, nr=3
    24 *-* call sysSleep sleepTime  -- sleep
    23 *-* sleepTime=random(1,750)/1000   -- get random sleep time
    22 *-* reply                 -- return & execute rest on new thread
       >>>   "0.672"
    24 *-* call sysSleep sleepTime  -- sleep
    23 *-* sleepTime=random(1,750)/1000   -- get random sleep time
       >>>   "0.369"
    24 *-* call sysSleep sleepTime  -- sleep
       >>>   "0"
    25 *-* say self": I got created as:" pp("#" nr)
       >I> Routine "PP" in package "G:\test_normal.rex".
    29 *-* return "[" || arg(1) || "]"
       >>>   "[# 3]"
       <I< Routine "PP" in package "G:\test_normal.rex".
       >>>   "a TEST: I got created as: [# 3]"
a TEST: I got created as: [# 3]
       >>>   "0"
    25 *-* say self": I got created as:" pp("#" nr)
       >I> Routine "PP" in package "G:\test_normal.rex".
    29 *-* return "[" || arg(1) || "]"
       >>>   "[# 1]"
       <I< Routine "PP" in package "G:\test_normal.rex".
       >>>   "a TEST: I got created as: [# 1]"
a TEST: I got created as: [# 1]
       >>>   "0"
    25 *-* say self": I got created as:" pp("#" nr)
       >I> Routine "PP" in package "G:\test_normal.rex".
    29 *-* return "[" || arg(1) || "]"
       >>>   "[# 2]"
       <I< Routine "PP" in package "G:\test_normal.rex".
       >>>   "a TEST: I got created as: [# 2]"
a TEST: I got created as: [# 2]