Product Site

15.4.3.2. Exploiting TraceObject's Profiling/Probing and Formatting Capabilities

This example extends the previous one and demonstrates how to take advantage of the capabilities the TraceObject class offers:

  • The class attribute option gets set to P (profiling/probing) which will cause ooRexx to not send the created TraceObject to .traceOutput such that no trace line will get displayed.

  • The class attribute collector gets an array assigned such that each created TraceObject will be sent to it using the APPEND message.

  • After the loop the main program sleeps for a second to wait long enough to be sure that all threads have completed and therefore all trace objects got generated and appended.

  • Taking advantage of the TraceObject formatting capabilities all trace objects collected in the array get displayed in a loop after setting the class attribute option to N (normal), T (thread), S (standard) and F (full). This way the collected trace objects get formatted such that more and more multithreaded related information gets revealed in the trace line.
Example 15.3. Exploiting TraceObject's Profiling/Probing Capability for Debugging a Multithreaded Program 
.TraceObject~option="P" -- set to "Profiling" ("Probing") mode
arr=.array~new          -- use an array to collect the traceObjects
.TraceObject~collector=arr -- assign array
do 3
  .test~new~show  -- create instance & send it the "show" message
end
call sysSleep 1         -- wait for the threads to end
say "arr~items:" arr~items "traceObjects collected"
.TraceObject~collector=.nil   -- stop collecting the traceObjects
say
say "now displaying the collected traceObjects in different formats:"
do counter c1 opt over "N", "T", "S", "F"
   .TraceObject~option=opt
   say "run #" c1", .TraceObject~option:" .TraceObject~option
   do traceObj over arr
      say traceObj      -- will cause makeString message to be sent
   end
   say "---"
end

::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
in SHOW, before reply, nr=2
in SHOW, before reply, nr=3
a TEST: I got created as: [# 3]
a TEST: I got created as: [# 1]
a TEST: I got created as: [# 2]
arr~items: 33 traceObjects collected

now displaying the collected traceObjects in different formats:
run # 1, .TraceObject~option: N
    38 *-* reply                 -- return & execute rest on new thread
    38 *-* reply                 -- return & execute rest on new thread
    39 *-* sleepTime=random(1,750)/1000   -- get random sleep time
       >>>   "0.563"
    40 *-* call sysSleep sleepTime  -- sleep
    39 *-* sleepTime=random(1,750)/1000   -- get random sleep time
       >>>   "0.614"
    40 *-* call sysSleep sleepTime  -- sleep
    38 *-* reply                 -- return & execute rest on new thread
    39 *-* sleepTime=random(1,750)/1000   -- get random sleep time
       >>>   "0.237"
    40 *-* call sysSleep sleepTime  -- sleep
       >>>   "0"
    41 *-* say self": I got created as:" pp("#" nr)
       >I> Routine "PP" in package "G:\test_show_off.rex".
    45 *-* return "[" || arg(1) || "]"
       >>>   "[# 3]"
       <I< Routine "PP" in package "G:\test_show_off.rex".
       >>>   "a TEST: I got created as: [# 3]"
       >>>   "0"
    41 *-* say self": I got created as:" pp("#" nr)
       >I> Routine "PP" in package "G:\test_show_off.rex".
    45 *-* return "[" || arg(1) || "]"
       >>>   "[# 1]"
       <I< Routine "PP" in package "G:\test_show_off.rex".
       >>>   "a TEST: I got created as: [# 1]"
       >>>   "0"
    41 *-* say self": I got created as:" pp("#" nr)
       >I> Routine "PP" in package "G:\test_show_off.rex".
    45 *-* return "[" || arg(1) || "]"
       >>>   "[# 2]"
       <I< Routine "PP" in package "G:\test_show_off.rex".
       >>>   "a TEST: I got created as: [# 2]"
---
run # 2, .TraceObject~option: T
    38 *-1* reply                 -- return & execute rest on new thread
    38 *-1* reply                 -- return & execute rest on new thread
    39 *-2* sleepTime=random(1,750)/1000   -- get random sleep time
       >>2>   "0.563"
    40 *-2* call sysSleep sleepTime  -- sleep
    39 *-3* sleepTime=random(1,750)/1000   -- get random sleep time
       >>3>   "0.614"
    40 *-3* call sysSleep sleepTime  -- sleep
    38 *-1* reply                 -- return & execute rest on new thread
    39 *-4* sleepTime=random(1,750)/1000   -- get random sleep time
       >>4>   "0.237"
    40 *-4* call sysSleep sleepTime  -- sleep
       >>4>   "0"
    41 *-4* say self": I got created as:" pp("#" nr)
       >I4> Routine "PP" in package "G:\test_show_off.rex".
    45 *-4* return "[" || arg(1) || "]"
       >>4>   "[# 3]"
       <I4< Routine "PP" in package "G:\test_show_off.rex".
       >>4>   "a TEST: I got created as: [# 3]"
       >>2>   "0"
    41 *-2* say self": I got created as:" pp("#" nr)
       >I2> Routine "PP" in package "G:\test_show_off.rex".
    45 *-2* return "[" || arg(1) || "]"
       >>2>   "[# 1]"
       <I2< Routine "PP" in package "G:\test_show_off.rex".
       >>2>   "a TEST: I got created as: [# 1]"
       >>3>   "0"
    41 *-3* say self": I got created as:" pp("#" nr)
       >I3> Routine "PP" in package "G:\test_show_off.rex".
    45 *-3* return "[" || arg(1) || "]"
       >>3>   "[# 2]"
       <I3< Routine "PP" in package "G:\test_show_off.rex".
       >>3>   "a TEST: I got created as: [# 2]"
---
run # 3, .TraceObject~option: S
[T1  I1  G  A1  L1  * ]     38 *-* reply                 -- return & execute rest on new thr
[T1  I2  G  A2  L1  * ]     38 *-* reply                 -- return & execute rest on new thr
[T2  I1  G  A1  L1  * ]     39 *-* sleepTime=random(1,750)/1000   -- get random sleep time
[T2  I1  G  A1  L1  * ]        >>>   "0.563"
[T2  I1  G  A1  L1  * ]     40 *-* call sysSleep sleepTime  -- sleep
[T3  I2  G  A2  L1  * ]     39 *-* sleepTime=random(1,750)/1000   -- get random sleep time
[T3  I2  G  A2  L1  * ]        >>>   "0.614"
[T3  I2  G  A2  L1  * ]     40 *-* call sysSleep sleepTime  -- sleep
[T1  I3  G  A3  L1  * ]     38 *-* reply                 -- return & execute rest on new thr
[T4  I3  G  A3  L1  * ]     39 *-* sleepTime=random(1,750)/1000   -- get random sleep time
[T4  I3  G  A3  L1  * ]        >>>   "0.237"
[T4  I3  G  A3  L1  * ]     40 *-* call sysSleep sleepTime  -- sleep
[T4  I3  G  A3  L1  * ]        >>>   "0"
[T4  I3  G  A3  L1  * ]     41 *-* say self": I got created as:" pp("#" nr)
[T4  I4 ]                      >I> Routine "PP" in package "G:\test_show_off.rex".
[T4  I4 ]                   45 *-* return "[" || arg(1) || "]"
[T4  I4 ]                      >>>   "[# 3]"
[T4  I4 ]                      <I< Routine "PP" in package "G:\test_show_off.rex".
[T4  I3  G  A3  L1  * ]        >>>   "a TEST: I got created as: [# 3]"
[T2  I1  G  A1  L1  * ]        >>>   "0"
[T2  I1  G  A1  L1  * ]     41 *-* say self": I got created as:" pp("#" nr)
[T2  I5 ]                      >I> Routine "PP" in package "G:\test_show_off.rex".
[T2  I5 ]                   45 *-* return "[" || arg(1) || "]"
[T2  I5 ]                      >>>   "[# 1]"
[T2  I5 ]                      <I< Routine "PP" in package "G:\test_show_off.rex".
[T2  I1  G  A1  L1  * ]        >>>   "a TEST: I got created as: [# 1]"
[T3  I2  G  A2  L1  * ]        >>>   "0"
[T3  I2  G  A2  L1  * ]     41 *-* say self": I got created as:" pp("#" nr)
[T3  I6 ]                      >I> Routine "PP" in package "G:\test_show_off.rex".
[T3  I6 ]                   45 *-* return "[" || arg(1) || "]"
[T3  I6 ]                      >>>   "[# 2]"
[T3  I6 ]                      <I< Routine "PP" in package "G:\test_show_off.rex".
[T3  I2  G  A2  L1  * ]        >>>   "a TEST: I got created as: [# 2]"
---
run # 4, .TraceObject~option: F
[R1   T1   I1    G  A1    L1   * ]     38 *-* reply                 -- return & execute rest
[R1   T1   I2    G  A2    L1   * ]     38 *-* reply                 -- return & execute rest
[R1   T2   I1    G  A1    L1   * ]     39 *-* sleepTime=random(1,750)/1000   -- get random s
[R1   T2   I1    G  A1    L1   * ]        >>>   "0.563"
[R1   T2   I1    G  A1    L1   * ]     40 *-* call sysSleep sleepTime  -- sleep
[R1   T3   I2    G  A2    L1   * ]     39 *-* sleepTime=random(1,750)/1000   -- get random s
[R1   T3   I2    G  A2    L1   * ]        >>>   "0.614"
[R1   T3   I2    G  A2    L1   * ]     40 *-* call sysSleep sleepTime  -- sleep
[R1   T1   I3    G  A3    L1   * ]     38 *-* reply                 -- return & execute rest
[R1   T4   I3    G  A3    L1   * ]     39 *-* sleepTime=random(1,750)/1000   -- get random s
[R1   T4   I3    G  A3    L1   * ]        >>>   "0.237"
[R1   T4   I3    G  A3    L1   * ]     40 *-* call sysSleep sleepTime  -- sleep
[R1   T4   I3    G  A3    L1   * ]        >>>   "0"
[R1   T4   I3    G  A3    L1   * ]     41 *-* say self": I got created as:" pp("#" nr)
[R1   T4   I4   ]                         >I> Routine "PP" in package "G:\test_show_off.rex"
[R1   T4   I4   ]                      45 *-* return "[" || arg(1) || "]"
[R1   T4   I4   ]                         >>>   "[# 3]"
[R1   T4   I4   ]                         <I< Routine "PP" in package "G:\test_show_off.rex"
[R1   T4   I3    G  A3    L1   * ]        >>>   "a TEST: I got created as: [# 3]"
[R1   T2   I1    G  A1    L1   * ]        >>>   "0"
[R1   T2   I1    G  A1    L1   * ]     41 *-* say self": I got created as:" pp("#" nr)
[R1   T2   I5   ]                         >I> Routine "PP" in package "G:\test_show_off.rex"
[R1   T2   I5   ]                      45 *-* return "[" || arg(1) || "]"
[R1   T2   I5   ]                         >>>   "[# 1]"
[R1   T2   I5   ]                         <I< Routine "PP" in package "G:\test_show_off.rex"
[R1   T2   I1    G  A1    L1   * ]        >>>   "a TEST: I got created as: [# 1]"
[R1   T3   I2    G  A2    L1   * ]        >>>   "0"
[R1   T3   I2    G  A2    L1   * ]     41 *-* say self": I got created as:" pp("#" nr)
[R1   T3   I6   ]                         >I> Routine "PP" in package "G:\test_show_off.rex"
[R1   T3   I6   ]                      45 *-* return "[" || arg(1) || "]"
[R1   T3   I6   ]                         >>>   "[# 2]"
[R1   T3   I6   ]                         <I< Routine "PP" in package "G:\test_show_off.rex"
[R1   T3   I2    G  A2    L1   * ]        >>>   "a TEST: I got created as: [# 2]"
---