As suggested by Rick in the past here as a first step a draft for adding documentation to the ooRexx
reference such that it becomes possible to communicate about the multithreaded trace prefix and its
meaning.
Starting out with the current documentation the nomenclatura is kept the same, possibly with
additional information meant for the debugging section in rexxref.pdf.
--- draft begin ---
15.4 Debugging Multithreaded Programs
ooRexx allows for executing different parts of ooRexx programs on multiple
threads of execution
using different Rexx interpreter within a single operating system process.
This makes it difficult and at times even impossible to debug such
multithreaded programs
without any additional information about the specific execution context.
Relevant information
for debugging multithreaded programs may be: the Rexx interpreter instance
that executes an
invocation ("activation") running on which operating system thread and
whether a lock is held
for exclusive access of an object's attribute ("object variable") pool.
To ease debugging of multithreaded programs the execution context can be
indicated with a
"multithreaded trace prefix" ("mtPrefix") string in the following form "[R1
T1 I5 G V1
L2 *]", where
* "R1": "R" stands for Rexx interpreter instance and the number (a
counter) indicates which of
the instances executes the current invocation (activation).
* "T1": "T" stands for (operating system) thread and the number (a
counter) indicates on which
of the currently existing threads the activity gets executed
* "I5": "I" stands for invocation (activation) and the number (a counter)
indicates which
invocation gets executed on that thread (activity)
Information in the mtPrefix if currently tracing statements of method
routines (otherwise the
remainder of the prefix will be blank):
* "G" or "U": this character indicates whether the method routine is
defined to be guarded or
unguarded.
* "V1" : "V" stands for "object variable dictionary" (attribute
dictionary) and the number (a
counter) indicates which object variable dictionary gets used in this
invocation of the
method routine. Each object will have its own object variable dictionary
which can be
directly accessed by method routines of the same scope, i.e. method
routines that are
defined in the same class from which the object got created. Therefore
the V indicator will
refer to the same object if the number is the same.
* "L2": "L" stands for object lock count and the number (a counter)
indicates how many object
lock reservations have taken place at that point in time. Whenever
another method routine of
the same scope gets invoked the object lock count increases by one, upon
return the object
lock count decreases by one.
* "*" or " ": the asterisk indicates that the activity holds the object
lock. Guarded methods
are blocked, if they do not hold the object lock. Methods in the
unguarded state will never
block.
Notes:
* the GUARD keyword instruction can be used within a method routine to
change the state from
guarded (synchronize on the object lock) to unguarded (ignore the object
lock) using
unconditionally the keyword statement GUARD OFF and vice versa (using
unconditionally the
keyword statement GUARD ON),
* the keyword instructions "GUARD ON someAttribute=someValue" and "GUARD
OFF
someAttribute=someValue" allow changing the state of the method routine
to guarded or to
unguarded depending on the value of an exposed attribute "someAttribute"
which needs to get
changed in another concurrently running method routine of the same
(class) scope. Such
attributes are known to be used as "control variables" to synchronize
activities on
different threads,
* if you wish to directly change the value of any exposed attribute then
make sure that the
changes take place in the guarded state to inhibit concurrent updates
from other threads to
inhibit inconsistent states,
* the object variable dictionary number represents a specific object,
* methods in the guarded state that do not possess the trailing asterisk
are blocked, they are
waiting for the object lock,
* methods in the unguarded state get never blocked,
* the standard layout of the mtPrefix is intentionally designed to make
parsing easy such that
analyzing the trace 3output of complex multithreaded ooRexx programs
becomes easy.
--- draft end ---
Here an informal (NOT part of the documentation for that a much simpler example would have to be
used) mtPrefix trace.
The program (ugly, but meant for demonstration, therefore the method name in the line comments in
each statement, allows for checking out what happens where):
thisName="(".context~name")" -- package say "before creating instance of
.oha" thisName --
package o=.oha~new -- package say "o="o thisName -- package o~m_22 --
package o~m_0 -- package
-- o~m_1 -- package o~m_22 -- package o~m_333 -- package exit -- package
::class oha ::method
init thisName="(".context~name")" -- INIT GUARDED say '*** hello from (m_1)'
thisName -- INIT
(before returning) ::method m_0 thisName="(".context~name")" -- m_0 GUARDED
say '*** before
self~m_0' thisName -- m_0 self~m_1 -- m_0 say '*** after self~m_0' thisName
-- m_0 (before
returning) ::method m_1 thisName="(".context~name")" -- m_1 GUARDED say '***
hello from (m_1)'
thisName -- m_1 reply -- m_1: remainder runs on new thread -- m_1 say
'before guard off (m_1)'
thisName -- m_1 guard off -- m_1 say 'after guard off (m_1)' thisName -- m_1
sleepTime=random(1,
10)/1000 -- m_1 say 'before sleeping (m_1)' sleepTime "seconds" thisName --
m_1 call sysSleep
sleepTime -- m_1 say 'after sleeping (m_1)' sleepTime "seconds is OVER"
thisName -- m_1 say
'before guard on (m_1)' thisName -- m_1 guard on -- m_1 say 'after guard on
(m_1)' thisName --
m_1 (before returning) ::method m_22 *unguarded*
thisName="(".context~name")" -- m_22 UNGUARDED
say '*** hello from (m_22)' thisName -- m_22 reply -- m_22: remainder runs
on new thread -- m_22
say 'before guard on (m_22)' thisName -- m_22 guard on -- m_22 say 'after
guard on (m_22)'
thisName -- m_22 sleepTime=random(1, 10)/1000 -- m_22 say 'before sleeping
(m_22)' sleepTime
"seconds" thisName -- m_22 call sysSleep sleepTime -- m_22 say 'after
sleeping (m_22)' sleepTime
"seconds is OVER" thisName -- m_22 say 'before guard off (m_22)' thisName --
m_22 guard off --
m_22 say 'after guard off (m_22)' thisName -- m_22 (before returning)
::method m_333
thisName="(".context~name")" -- m_333 GUARDED say '*** hello from (m_333)'
thisName -- m_333
reply -- m_333: remainder runs on new thread say 'before guard off (m_333)'
thisName -- m_333
guard off -- m_333 say 'after guard off (m_333)' thisName -- m_333
sleepTime=random(1, 10)/1000
-- m_333 say 'before sleeping (m_333)' sleepTime "seconds" thisName -- m_333
call sysSleep
sleepTime -- m_333 say 'after sleeping (m_333)' sleepTime "seconds is OVER"
thisName -- m_333
say 'before guard on (m_333)' thisName -- m_333 guard on -- m_333 say 'after
guard on (m_333)'
thisName -- m_333 (before returning) ::options trace r
Here running the above program with mtPrefix on:
[R1 T1 I1 ] 1 *-* thisName="(".context~name")" -- package [R1 T1 I1 ] >>>
"(G:\test\orx\trace\20240120\conc.rex)" [R1 T1 I1 ] 2 *-* say "before creating
instance of .oha"
thisName -- package [R1 T1 I1 ] >>> "before creating instance of .oha
(G:\test\orx\trace\20240120\conc.rex)" before creating instance of .oha
(G:\test\orx\trace\20240120\conc.rex) [R1 T1 I1 ] 3 *-* o=.oha~new --
package [R1 T1 I2 G V1 L0
] >I> Method "INIT" with scope "OHA" in package
"G:\test\orx\trace\20240120\conc.rex". [R1 T1 I2
G V1 L1 *] 14 *-* thisName="(".context~name")" -- INIT GUARDED [R1 T1 I2 G V1 L1 *]
>>> "(INIT)"
[R1 T1 I2 G V1 L1 *] 15 *-* say '*** hello from (m_1)' thisName -- INIT
(before returning) [R1
T1 I2 G V1 L1 *] >>> "*** hello from (m_1) (INIT)" *** hello from (m_1) (INIT) [R1 T1
I1 ] >>>
"an OHA" [R1 T1 I1 ] 4 *-* say "o="o thisName -- package [R1 T1 I1 ] >>>
"o=an OHA
(G:\test\orx\trace\20240120\conc.rex)" o=an OHA
(G:\test\orx\trace\20240120\conc.rex) [R1 T1 I1
] 5 *-* o~m_22 -- package [R1 T1 I3 U V1 L0 ] >I> Method "M_22" with scope
"OHA" in package
"G:\test\orx\trace\20240120\conc.rex". [R1 T1 I3 U V1 L0 ] 39 *-*
thisName="(".context~name")"
-- m_22 UNGUARDED [R1 T1 I3 U V1 L0 ] >>> "(M_22)" [R1 T1 I3 U V1 L0 ] 40
*-* say '*** hello
from (m_22)' thisName -- m_22 [R1 T1 I3 U V1 L0 ] >>> "*** hello from (m_22)
(M_22)" *** hello
from (m_22) (M_22) [R1 T1 I3 U V1 L0 ] 41 *-* reply -- m_22: remainder runs
on new thread --
m_22 [R1 T1 I1 ] 6 *-* o~m_0 -- package [R1 T1 I4 G V1 L0 ] >I> Method "M_0" with
scope "OHA" in
package "G:\test\orx\trace\20240120\conc.rex". [R1 T1 I4 G V1 L1 *] 18 *-*
thisName="(".context~name")" -- m_0 GUARDED [R1 T2 I3 U V1 L1 ] >I> Method
"M_22" with scope
"OHA" in package "G:\test\orx\trace\20240120\conc.rex". [R1 T1 I4 G V1 L1 *] >>>
"(M_0)" [R1 T2
I3 U V1 L1 ] 42 *-* say 'before guard on (m_22)' thisName -- m_22 [R1 T1 I4
G V1 L1 *] 19 *-*
say '*** before self~m_0' thisName -- m_0 [R1 T2 I3 U V1 L1 ] >>> "before
guard on (m_22)
(M_22)" before guard on (m_22) (M_22) [R1 T1 I4 G V1 L1 *] >>> "*** before
self~m_0 (M_0)" ***
before self~m_0 (M_0) [R1 T2 I3 U V1 L1 ] 43 *-* guard on -- m_22 [R1 T1 I4
G V1 L1 *] 20 *-*
self~m_1 -- m_0 [R1 T1 I5 G V1 L1 ] >I> Method "M_1" with scope "OHA" in
package
"G:\test\orx\trace\20240120\conc.rex". [R1 T1 I5 G V1 L2 *] 24 *-*
thisName="(".context~name")"
-- m_1 GUARDED [R1 T1 I5 G V1 L2 *] >>> "(M_1)" [R1 T1 I5 G V1 L2 *] 25 *-*
say '*** hello from
(m_1)' thisName -- m_1 [R1 T1 I5 G V1 L2 *] >>> "*** hello from (m_1) (M_1)"
*** hello from
(m_1) (M_1) [R1 T1 I5 G V1 L2 *] 26 *-* reply -- m_1: remainder runs on new
thread -- m_1 [R1 T1
I4 G V1 L1 *] 21 *-* say '*** after self~m_0' thisName -- m_0 (before
returning) [R1 T1 I4 G V1
L1 *] >>> "*** after self~m_0 (M_0)" *** after self~m_0 (M_0) [R1 T1 I1 ] 8
*-* o~m_22 --
package [R1 T1 I6 U V1 L1 ] >I> Method "M_22" with scope "OHA" in package
"G:\test\orx\trace\20240120\conc.rex". [R1 T2 I3 U V1 L1 *] 44 *-* say
'after guard on (m_22)'
thisName -- m_22 [R1 T1 I6 U V1 L1 ] 39 *-* thisName="(".context~name")" --
m_22 UNGUARDED [R1
T2 I3 U V1 L1 *] >>> "after guard on (m_22) (M_22)" after guard on (m_22)
(M_22) [R1 T1 I6 U V1
L1 ] >>> "(M_22)" [R1 T2 I3 U V1 L1 *] 45 *-* sleepTime=random(1, 10)/1000
-- m_22 [R1 T1 I6 U
V1 L1 ] 40 *-* say '*** hello from (m_22)' thisName -- m_22 [R1 T2 I3 U V1 L1 *] >>>
"0.002" [R1
T1 I6 U V1 L1 ] >>> "*** hello from (m_22) (M_22)" *** hello from (m_22)
(M_22) [R1 T2 I3 U V1
L1 *] 46 *-* say 'before sleeping (m_22)' sleepTime "seconds" thisName --
m_22 [R1 T1 I6 U V1 L1
] 41 *-* reply -- m_22: remainder runs on new thread -- m_22 [R1 T2 I3 U V1 L1 *]
>>> "before
sleeping (m_22) 0.002 seconds (M_22)" before sleeping (m_22) 0.002 seconds
(M_22) [R1 T1 I1 ] 9
*-* o~m_333 -- package [R1 T2 I3 U V1 L1 *] 47 *-* call sysSleep sleepTime
-- m_22 [R1 T3 I6 U
V1 L1 ] >I> Method "M_22" with scope "OHA" in package
"G:\test\orx\trace\20240120\conc.rex". [R1
T1 I7 G V1 L1 ] >I> Method "M_333" with scope "OHA" in package
"G:\test\orx\trace\20240120\conc.rex". [R1 T3 I6 U V1 L1 ] 42 *-* say
'before guard on (m_22)'
thisName -- m_22 [R1 T3 I6 U V1 L1 ] >>> "before guard on (m_22) (M_22)"
before guard on (m_22)
(M_22) [R1 T3 I6 U V1 L1 ] 43 *-* guard on -- m_22 [R1 T2 I3 U V1 L1 *] >>>
"0" [R1 T2 I3 U V1
L1 *] 48 *-* say 'after sleeping (m_22)' sleepTime "seconds is OVER"
thisName -- m_22 [R1 T2 I3
U V1 L1 *] >>> "after sleeping (m_22) 0.002 seconds is OVER (M_22)" after
sleeping (m_22) 0.002
seconds is OVER (M_22) [R1 T2 I3 U V1 L1 *] 49 *-* say 'before guard off
(m_22)' thisName --
m_22 [R1 T2 I3 U V1 L1 *] >>> "before guard off (m_22) (M_22)" before guard
off (m_22) (M_22)
[R1 T2 I3 U V1 L1 *] 50 *-* guard off -- m_22 [R1 T2 I3 U V1 L1 ] 51 *-* say
'after guard off
(m_22)' thisName -- m_22 (before returning) [R1 T4 I5 G V1 L1 *] >I> Method
"M_1" with scope
"OHA" in package "G:\test\orx\trace\20240120\conc.rex". [R1 T2 I3 U V1 L1 ] >>>
"after guard off
(m_22) (M_22)" after guard off (m_22) (M_22) [R1 T4 I5 G V1 L1 *] 27 *-* say
'before guard off
(m_1)' thisName -- m_1 [R1 T4 I5 G V1 L1 *] >>> "before guard off (m_1)
(M_1)" before guard off
(m_1) (M_1) [R1 T4 I5 G V1 L1 *] 28 *-* guard off -- m_1 [R1 T4 I5 G V1 L1 ]
29 *-* say 'after
guard off (m_1)' thisName -- m_1 [R1 T4 I5 G V1 L1 ] >>> "after guard off (m_1)
(M_1)" after
guard off (m_1) (M_1) [R1 T4 I5 G V1 L1 ] 30 *-* sleepTime=random(1,
10)/1000 -- m_1 [R1 T4 I5 G
V1 L1 ] >>> "0.01" [R1 T4 I5 G V1 L1 ] 31 *-* say 'before sleeping (m_1)' sleepTime
"seconds"
thisName -- m_1 [R1 T4 I5 G V1 L1 ] >>> "before sleeping (m_1) 0.01 seconds
(M_1)" before
sleeping (m_1) 0.01 seconds (M_1) [R1 T4 I5 G V1 L1 ] 32 *-* call sysSleep
sleepTime -- m_1 [R1
T1 I7 G V1 L1 *] 55 *-* thisName="(".context~name")" -- m_333 GUARDED [R1 T1 I7 G V1
L1 *] >>>
"(M_333)" [R1 T1 I7 G V1 L1 *] 56 *-* say '*** hello from (m_333)' thisName
-- m_333 [R1 T1 I7 G
V1 L1 *] >>> "*** hello from (m_333) (M_333)" *** hello from (m_333) (M_333)
[R1 T1 I7 G V1 L1
*] 57 *-* reply -- m_333: remainder runs on new thread [R1 T1 I1 ] 10 *-*
exit -- package [R1 T2
I7 G V1 L1 *] >I> Method "M_333" with scope "OHA" in package
"G:\test\orx\trace\20240120\conc.rex". [R1 T2 I7 G V1 L1 *] 58 *-* say
'before guard off
(m_333)' thisName -- m_333 [R1 T2 I7 G V1 L1 *] >>> "before guard off (m_333)
(M_333)" before
guard off (m_333) (M_333) [R1 T2 I7 G V1 L1 *] 59 *-* guard off -- m_333 [R1
T2 I7 G V1 L1 ] 60
*-* say 'after guard off (m_333)' thisName -- m_333 [R1 T3 I6 U V1 L1 *] 44
*-* say 'after guard
on (m_22)' thisName -- m_22 [R1 T2 I7 G V1 L1 ] >>> "after guard off (m_333)
(M_333)" after
guard off (m_333) (M_333) [R1 T3 I6 U V1 L1 *] >>> "after guard on (m_22)
(M_22)" after guard on
(m_22) (M_22) [R1 T2 I7 G V1 L1 ] 61 *-* sleepTime=random(1, 10)/1000 --
m_333 [R1 T3 I6 U V1 L1
*] 45 *-* sleepTime=random(1, 10)/1000 -- m_22 [R1 T2 I7 G V1 L1 ] >>>
"0.005" [R1 T3 I6 U V1 L1
*] >>> "0.002" [R1 T2 I7 G V1 L1 ] 62 *-* say 'before sleeping (m_333)' sleepTime
"seconds"
thisName -- m_333 [R1 T3 I6 U V1 L1 *] 46 *-* say 'before sleeping (m_22)' sleepTime
"seconds"
thisName -- m_22 [R1 T2 I7 G V1 L1 ] >>> "before sleeping (m_333) 0.005 seconds
(M_333)" before
sleeping (m_333) 0.005 seconds (M_333) [R1 T3 I6 U V1 L1 *] >>> "before
sleeping (m_22) 0.002
seconds (M_22)" before sleeping (m_22) 0.002 seconds (M_22) [R1 T2 I7 G V1
L1 ] 63 *-* call
sysSleep sleepTime -- m_333 [R1 T3 I6 U V1 L1 *] 47 *-* call sysSleep
sleepTime -- m_22 [R1 T3
I6 U V1 L1 *] >>> "0" [R1 T2 I7 G V1 L1 ] >>> "0" [R1 T4 I5 G V1 L1 ] >>>
"0" [R1 T3 I6 U V1 L1
*] 48 *-* say 'after sleeping (m_22)' sleepTime "seconds is OVER" thisName
-- m_22 [R1 T2 I7 G
V1 L1 ] 64 *-* say 'after sleeping (m_333)' sleepTime "seconds is OVER"
thisName -- m_333 [R1 T4
I5 G V1 L1 ] 33 *-* say 'after sleeping (m_1)' sleepTime "seconds is OVER"
thisName -- m_1 [R1
T3 I6 U V1 L1 *] >>> "after sleeping (m_22) 0.002 seconds is OVER (M_22)"
after sleeping (m_22)
0.002 seconds is OVER (M_22) [R1 T2 I7 G V1 L1 ] >>> "after sleeping (m_333)
0.005 seconds is
OVER (M_333)" after sleeping (m_333) 0.005 seconds is OVER (M_333) [R1 T4 I5 G V1 L1
] >>>
"after sleeping (m_1) 0.01 seconds is OVER (M_1)" after sleeping (m_1) 0.01
seconds is OVER
(M_1) [R1 T3 I6 U V1 L1 *] 49 *-* say 'before guard off (m_22)' thisName --
m_22 [R1 T2 I7 G V1
L1 ] 65 *-* say 'before guard on (m_333)' thisName -- m_333 [R1 T4 I5 G V1
L1 ] 34 *-* say
'before guard on (m_1)' thisName -- m_1 [R1 T3 I6 U V1 L1 *] >>> "before
guard off (m_22)
(M_22)" before guard off (m_22) (M_22) [R1 T2 I7 G V1 L1 ] >>> "before guard on
(m_333) (M_333)"
before guard on (m_333) (M_333) [R1 T4 I5 G V1 L1 ] >>> "before guard on (m_1)
(M_1)" before
guard on (m_1) (M_1) [R1 T3 I6 U V1 L1 *] 50 *-* guard off -- m_22 [R1 T2 I7
G V1 L1 ] 66 *-*
guard on -- m_333 [R1 T4 I5 G V1 L1 ] 35 *-* guard on -- m_1 [R1 T3 I6 U V1
L0 ] 51 *-* say
'after guard off (m_22)' thisName -- m_22 (before returning) [R1 T2 I7 G V1
L1 *] 67 *-* say
'after guard on (m_333)' thisName -- m_333 (before returning) [R1 T3 I6 U V1 L1 ]
>>> "after
guard off (m_22) (M_22)" after guard off (m_22) (M_22) [R1 T2 I7 G V1 L1 *] >>>
"after guard on
(m_333) (M_333)" after guard on (m_333) (M_333) [R1 T4 I5 G V1 L1 *] 36 *-*
say 'after guard on
(m_1)' thisName -- m_1 (before returning) [R1 T4 I5 G V1 L1 *] >>> "after guard
on (m_1) (M_1)"
after guard on (m_1) (M_1)
What follows next is a proposal on how to activate the mtPrefix and how to allow Rexx programmers to
create their own mtPrefix.
---rony
_______________________________________________
Oorexx-devel mailing list
Oorexx-devel@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/oorexx-devel
