-
Notifications
You must be signed in to change notification settings - Fork 1
Circular Memory Buffer
Eric Flumerfelt edited this page Jun 17, 2022
·
1 revision
{{toc}}
Assuming TRACE is setup — that the convenience functions/aliases are in the environment…
There are at least 7 trace_cntl commands (or convenience
functions/aliases) to master
to effectively use memory tracing. Additionally, grep is often used to
filter the lines
in the memory buffer.
To enable memory TRACEing, one of the first 7 env. vars in the “tenv env
list” (see below/next)
has to be set, either in the environment or by the program.
The first four of these variables effect fundamental parameters of the
memory buffer, but
only if they cause the creation of the buffer (as opposed to the use of
a previously created
buffer). An exception to this is the special case of TRACE_MSGMAX=0
which causes the
default value (128) to be used if creating the memory buffer.
$ export TRACE_MSGMAX=0
$ tenv
TRACE_NAMTBLENTS
TRACE_NUMENTS
TRACE_ARGSMAX
TRACE_MSGMAX=0
TRACE_NAME
TRACE_FILE
TRACE_LVLM=
TRACE_ENDL
TRACE_LIMIT_MS
TRACE_LVLS
TRACE_MODE
TRACE_NAMLVLSET
TRACE_PRINT_FD
TRACE_SHOW
TRACE_TIME_FMT
The line with the “=” indicates that TRACE_MSGMAX is the only variable
set, in this example.
The default TRACE_FILE is /tmp/trace_buffer_$USER. Executing “tinfo”
in
this environment will create the memory buffer file if doesn’t exists,
then
display the info about the file:
$ rm -f /tmp/trace_buffer_$USER
$ tinfo
trace.h rev = $Revision: 682 $$Date: 2017-11-09 14:01:41 -0600 (Thu, 09 Nov 2017) $
revision = $Revision: 682 $$Date: 2017-11-09 14:01:41 -0600 (Thu, 09 Nov 2017) $
create time = Thu Nov 09 14:14:31 CST 2017
trace_initialized =1
mode =0x3 Slow:ON, Mem:ON
writeIdxCount =0x00000000 entries used: 0
full =0
nameLock =0
largestMultiple =0xffffbc70
trigIdxCnt =0x00000000
triggered =0
trigActivePost =0
limit_cnt_limit =0
limit_span_on_ms =0
limit_span_off_ms =0
traceLevel =0x000000000000000f 0x0000000000000007
num_entries =50000 <---<<< TRACE_NUMENTS
max_msg_sz =128 includes system enforced terminator <---<<< TRACE_MSGMAX
max_params =10 <---<<< TRACE_ARGSMAX
entry_size =256
namLvlTbl_ents =127 <---<<< TRACE_NAMTBLENTS
namLvlTbl_name_sz =40
longest_name =7
wrIdxCnt offset =0x10000
namLvls offset =0xfffffffffebd10c0
buffer_offset =0xfffffffffebd3080
memlen =12910592
default TRACE_SHOW=HxNTPiCnLR others: t(tsc) B(paramBytes) s(slot) m(convertedMsgfmt_only) D(inDent) I(TID) #(nargs) l(lvl int)
Note: I’ve added the “<—-<<< …” in the above to indicate the values
controlled by the
variables when the file is created.
TRACE_FILE can be set to the path to a trace_buffer_file. The parent
directories
must exists. The path can be on a network file system, but simultaneous
access from
multiple nodes is not supported.
The tonMg command can be used to turn memory tracing on for all
currently defined and also the undefined (future)
TRACE names. The toffS command with the -n option can be used to
turn of the standard out tracing for a
particular trace name. This will be used along with the
tshow|grep|tdelta pipeline to see the difference in timing
behavior between the threads in the example (next).
$ tonMg 0-63;toffS 0-2 -nTEST_THR_0
$ tlvls
mode: M=1 S=1
TID NAME maskM maskS maskT
--- ---------- ------------------ ------------------ ------------------
0 TEST_THR_0 0xffffffffffffffff 0x0000000000000000 0x0000000000000000
125 TRACE 0xffffffffffffffff 0x0000000000000007 0x0000000000000000
126 _TRACE_ 0xffffffffffffffff 0x0000000000000007 0x0000000000000000
In the above, the -n option is given to the tonMg command.
-n sets the TRACE_NAME in the
commands environment, which will create the name in the names-levels
table if it does not already exist.
When new TRACE names are registered/created, the default maskM (Memory)
and maskS (Slow)
are 0xf and 0x7, respectively. tonMg is the “global” variant of the tonM
command - it will turn on (set)
the specified levels for all the existing Name entries.
An empty memory buffer:
$ tshow
idx us_tod pid tid cpu name lvl r msg
--- ---------------- ----- ----- --- ----------- --- - -----------------------------
(END)
Note: both the tshow and tdelta commands recognize the PAGER env.var,
which in this case
is set to less, and hence, the “(END)” in the above output
To fill the memory buffer for this example, “tcntl test-threads” can be used.
The “tcntl test-threads” (as will be used) will create TRACE names for each of four threads “TEST_THR_[0-3]”.
$ tcntl test-threads -x2; tshow|tac|tdelta -d 1 -ct 1 -i
11-10 16:42:27.416389 TRACE wrn before pthread_create - loops=2, threads=4, dly_ms=0 traceControl_p=0x7fb19f1a4000
11-10 16:42:27.416608 TEST_THR_2 inf tidx=2 loop=1 of 2 tid=29949 I need to test longer messages. They need to be about 256 characters - longer than the circular memory message buffer size. This will check for message mangling
11-10 16:42:27.416634 TEST_THR_2 inf tidx=2 loop=1 of 2 tid=29949 this is the second long message - second0 second1 second2 second3 second4 second5 second6 second7 second8 second9
11-10 16:42:27.416621 TEST_THR_1 inf tidx=1 loop=1 of 2 tid=29948 I need to test longer messages. They need to be about 256 characters - longer than the circular memory message buffer size. This will check for message mangling
11-10 16:42:27.416635 TEST_THR_3 inf tidx=3 loop=1 of 2 tid=29950 I need to test longer messages. They need to be about 256 characters - longer than the circular memory message buffer size. This will check for message mangling
11-10 16:42:27.416655 TEST_THR_3 inf tidx=3 loop=1 of 2 tid=29950 this is the second long message - second0 second1 second2 second3 second4 second5 second6 second7 second8 second9
11-10 16:42:27.416662 TEST_THR_3 inf tidx=3 loop=2 of 2 tid=29950 I need to test longer messages. They need to be about 256 characters - longer than the circular memory message buffer size. This will check for message mangling
11-10 16:42:27.416667 TEST_THR_3 inf tidx=3 loop=2 of 2 tid=29950 this is the second long message - second0 second1 second2 second3 second4 second5 second6 second7 second8 second9
11-10 16:42:27.416670 TEST_THR_2 inf tidx=2 loop=2 of 2 tid=29949 I need to test longer messages. They need to be about 256 characters - longer than the circular memory message buffer size. This will check for message mangling
11-10 16:42:27.416652 TEST_THR_1 inf tidx=1 loop=1 of 2 tid=29948 this is the second long message - second0 second1 second2 second3 second4 second5 second6 second7 second8 second9
11-10 16:42:27.416675 TEST_THR_2 inf tidx=2 loop=2 of 2 tid=29949 this is the second long message - second0 second1 second2 second3 second4 second5 second6 second7 second8 second9
11-10 16:42:27.416697 TEST_THR_1 inf tidx=1 loop=2 of 2 tid=29948 I need to test longer messages. They need to be about 256 characters - longer than the circular memory message buffer size. This will check for message mangling
11-10 16:42:27.416706 TEST_THR_1 inf tidx=1 loop=2 of 2 tid=29948 this is the second long message - second0 second1 second2 second3 second4 second5 second6 second7 second8 second9
11-10 16:42:27.417438 TRACE wrn after pthread_join - traceControl_p=0x7fb19f1a4000
41 11-10 16:42:27.416389 0 29946 29946 20 TRACE wrn . before pthread_create - loops=2, threads=4, dly_ms=0 traceControl_p=0x7fb19f1a4000
40 11-10 16:42:27.416608 219 29946 29949 21 TEST_THR_2 inf . tidx=2 loop=1 of 2 tid=29949 I need to test longer messages. They need to be about 256 characters - longer than the circular me
39 11-10 16:42:27.416612 4 29946 29947 13 TEST_THR_0 inf . tidx=0 loop=1 of 2 tid=29947 I need to test longer messages. They need to be about 256 characters - longer than the circular me
38 11-10 16:42:27.416614 2 29946 29947 13 TEST_THR_0 inf . tidx=0 loop=1 of 2 tid=29947 this is the second long message - second0 second1 second2 second3 second4 second5 second6 second7
37 11-10 16:42:27.416615 1 29946 29947 13 TEST_THR_0 dbg . tidx=0 loop=1 of 2 tid=29947 this is the third long message - third0 third1 third2 third3 third4 third5 third6 third7 third8 th
36 11-10 16:42:27.416615 0 29946 29947 13 TEST_THR_0 d04 . tidx=0 loop=1 of 2 tid=29947 this is the fourth long message - fourth0 fourth1 fourth2 fourth3 fourth4 fourth5 fourth6 fourth7
35 11-10 16:42:27.416616 1 29946 29947 13 TEST_THR_0 d05 . tidx=0 loop=1 of 2 tid=29947 - extra, if enabled
34 11-10 16:42:27.416616 0 29946 29947 13 TEST_THR_0 inf . tidx=0 loop=2 of 2 tid=29947 I need to test longer messages. They need to be about 256 characters - longer than the circular me
33 11-10 16:42:27.416616 0 29946 29947 13 TEST_THR_0 inf . tidx=0 loop=2 of 2 tid=29947 this is the second long message - second0 second1 second2 second3 second4 second5 second6 second7
32 11-10 16:42:27.416616 0 29946 29947 13 TEST_THR_0 dbg . tidx=0 loop=2 of 2 tid=29947 this is the third long message - third0 third1 third2 third3 third4 third5 third6 third7 third8 th
31 11-10 16:42:27.416617 1 29946 29947 13 TEST_THR_0 d04 . tidx=0 loop=2 of 2 tid=29947 this is the fourth long message - fourth0 fourth1 fourth2 fourth3 fourth4 fourth5 fourth6 fourth7
30 11-10 16:42:27.416617 0 29946 29947 13 TEST_THR_0 d05 . tidx=0 loop=2 of 2 tid=29947 - extra, if enabled
29 11-10 16:42:27.416621 4 29946 29948 14 TEST_THR_1 inf . tidx=1 loop=1 of 2 tid=29948 I need to test longer messages. They need to be about 256 characters - longer than the circular me
28 11-10 16:42:27.416634 13 29946 29949 21 TEST_THR_2 inf . tidx=2 loop=1 of 2 tid=29949 this is the second long message - second0 second1 second2 second3 second4 second5 second6 second7
27 11-10 16:42:27.416635 1 29946 29950 22 TEST_THR_3 inf . tidx=3 loop=1 of 2 tid=29950 I need to test longer messages. They need to be about 256 characters - longer than the circular me
26 11-10 16:42:27.416639 4 29946 29949 21 TEST_THR_2 dbg . tidx=2 loop=1 of 2 tid=29949 this is the third long message - third0 third1 third2 third3 third4 third5 third6 third7 third8 th
25 11-10 16:42:27.416652 13 29946 29948 14 TEST_THR_1 inf . tidx=1 loop=1 of 2 tid=29948 this is the second long message - second0 second1 second2 second3 second4 second5 second6 second7
24 11-10 16:42:27.416655 3 29946 29950 22 TEST_THR_3 inf . tidx=3 loop=1 of 2 tid=29950 this is the second long message - second0 second1 second2 second3 second4 second5 second6 second7
23 11-10 16:42:27.416661 6 29946 29950 22 TEST_THR_3 dbg . tidx=3 loop=1 of 2 tid=29950 this is the third long message - third0 third1 third2 third3 third4 third5 third6 third7 third8 th
22 11-10 16:42:27.416661 0 29946 29950 22 TEST_THR_3 d04 . tidx=3 loop=1 of 2 tid=29950 this is the fourth long message - fourth0 fourth1 fourth2 fourth3 fourth4 fourth5 fourth6 fourth7
21 11-10 16:42:27.416662 1 29946 29950 22 TEST_THR_3 d05 . tidx=3 loop=1 of 2 tid=29950 - extra, if enabled
20 11-10 16:42:27.416662 0 29946 29950 22 TEST_THR_3 inf . tidx=3 loop=2 of 2 tid=29950 I need to test longer messages. They need to be about 256 characters - longer than the circular me
19 11-10 16:42:27.416667 5 29946 29950 22 TEST_THR_3 inf . tidx=3 loop=2 of 2 tid=29950 this is the second long message - second0 second1 second2 second3 second4 second5 second6 second7
18 11-10 16:42:27.416669 2 29946 29949 21 TEST_THR_2 d04 . tidx=2 loop=1 of 2 tid=29949 this is the fourth long message - fourth0 fourth1 fourth2 fourth3 fourth4 fourth5 fourth6 fourth7
17 11-10 16:42:27.416670 1 29946 29949 21 TEST_THR_2 d05 . tidx=2 loop=1 of 2 tid=29949 - extra, if enabled
16 11-10 16:42:27.416670 0 29946 29949 21 TEST_THR_2 inf . tidx=2 loop=2 of 2 tid=29949 I need to test longer messages. They need to be about 256 characters - longer than the circular me
15 11-10 16:42:27.416670 0 29946 29950 22 TEST_THR_3 dbg . tidx=3 loop=2 of 2 tid=29950 this is the third long message - third0 third1 third2 third3 third4 third5 third6 third7 third8 th
14 11-10 16:42:27.416670 0 29946 29950 22 TEST_THR_3 d04 . tidx=3 loop=2 of 2 tid=29950 this is the fourth long message - fourth0 fourth1 fourth2 fourth3 fourth4 fourth5 fourth6 fourth7
13 11-10 16:42:27.416671 1 29946 29950 22 TEST_THR_3 d05 . tidx=3 loop=2 of 2 tid=29950 - extra, if enabled
12 11-10 16:42:27.416675 4 29946 29949 21 TEST_THR_2 inf . tidx=2 loop=2 of 2 tid=29949 this is the second long message - second0 second1 second2 second3 second4 second5 second6 second7
11 11-10 16:42:27.416681 6 29946 29948 14 TEST_THR_1 dbg . tidx=1 loop=1 of 2 tid=29948 this is the third long message - third0 third1 third2 third3 third4 third5 third6 third7 third8 th
10 11-10 16:42:27.416681 0 29946 29948 14 TEST_THR_1 d04 . tidx=1 loop=1 of 2 tid=29948 this is the fourth long message - fourth0 fourth1 fourth2 fourth3 fourth4 fourth5 fourth6 fourth7
9 11-10 16:42:27.416683 2 29946 29949 21 TEST_THR_2 dbg . tidx=2 loop=2 of 2 tid=29949 this is the third long message - third0 third1 third2 third3 third4 third5 third6 third7 third8 th
8 11-10 16:42:27.416689 6 29946 29949 21 TEST_THR_2 d04 . tidx=2 loop=2 of 2 tid=29949 this is the fourth long message - fourth0 fourth1 fourth2 fourth3 fourth4 fourth5 fourth6 fourth7
7 11-10 16:42:27.416689 0 29946 29949 21 TEST_THR_2 d05 . tidx=2 loop=2 of 2 tid=29949 - extra, if enabled
6 11-10 16:42:27.416697 8 29946 29948 14 TEST_THR_1 d05 . tidx=1 loop=1 of 2 tid=29948 - extra, if enabled
5 11-10 16:42:27.416697 0 29946 29948 14 TEST_THR_1 inf . tidx=1 loop=2 of 2 tid=29948 I need to test longer messages. They need to be about 256 characters - longer than the circular me
4 11-10 16:42:27.416706 9 29946 29948 14 TEST_THR_1 inf . tidx=1 loop=2 of 2 tid=29948 this is the second long message - second0 second1 second2 second3 second4 second5 second6 second7
3 11-10 16:42:27.416710 4 29946 29948 14 TEST_THR_1 dbg . tidx=1 loop=2 of 2 tid=29948 this is the third long message - third0 third1 third2 third3 third4 third5 third6 third7 third8 th
2 11-10 16:42:27.416710 0 29946 29948 14 TEST_THR_1 d04 . tidx=1 loop=2 of 2 tid=29948 this is the fourth long message - fourth0 fourth1 fourth2 fourth3 fourth4 fourth5 fourth6 fourth7
1 11-10 16:42:27.416711 1 29946 29948 14 TEST_THR_1 d05 . tidx=1 loop=2 of 2 tid=29948 - extra, if enabled
0 11-10 16:42:27.417438 727 29946 29946 20 TRACE wrn . after pthread_join - traceControl_p=0x7fb19f1a4000
--- ---------------- --------- ----- ----- --- ---------- --- - -----------------------------
idx us_tod delta pid tid cpu name lvl r msg
tcntl test-threads, with no options or parameters, creates 4 threads
which will each loop twice with 5 TRACEs per loop —> 5*2*4=40 TRACEs
from
the threads go to memory. There is also 2 additional TRACEs from the
main thread, hence the idx column goes from 0 to 41.
There are several things to notice:
- A subset of these 40 TRACEs also go to stdout.
- The TRACE buffer is printed/displayed by the tshow command which
typically prints the lines in
reverse chronological order. The unix tac is used in the example to “flip” the whole output so the
order matches the standard output order. - The tshow output is piped into tdelta which converts the time column
(-ct 1) and also adds a delta
column based on the time column (-d 1).
Note: the default (unconverted) tshow time column is the unix system
time in microsecond since the standard
unix epoch. This is an absolute time which allows deltas to be
calculated on filtered output (see below).
The difference bewteen a thread that does some stdout and one that doesn’t:
$ tshow | grep TEST_THR_1 | tdelta -d 1 -stats
1 1510353747416711 0 29946 29948 14 TEST_THR_1 d05 . tidx=1 loop=2 of 2 tid=29948 - extra, if enabled
2 1510353747416710 1 29946 29948 14 TEST_THR_1 d04 . tidx=1 loop=2 of 2 tid=29948 this is the fourth long message - fourth0 fourth1 fourth2 fourth3 fourth4 fourth5 fourth6 fourth7
3 1510353747416710 0 29946 29948 14 TEST_THR_1 dbg . tidx=1 loop=2 of 2 tid=29948 this is the third long message - third0 third1 third2 third3 third4 third5 third6 third7 third8 th
4 1510353747416706 4 29946 29948 14 TEST_THR_1 inf . tidx=1 loop=2 of 2 tid=29948 this is the second long message - second0 second1 second2 second3 second4 second5 second6 second7
5 1510353747416697 9 29946 29948 14 TEST_THR_1 inf . tidx=1 loop=2 of 2 tid=29948 I need to test longer messages. They need to be about 256 characters - longer than the circular me
6 1510353747416697 0 29946 29948 14 TEST_THR_1 d05 . tidx=1 loop=1 of 2 tid=29948 - extra, if enabled
10 1510353747416681 16 29946 29948 14 TEST_THR_1 d04 . tidx=1 loop=1 of 2 tid=29948 this is the fourth long message - fourth0 fourth1 fourth2 fourth3 fourth4 fourth5 fourth6 fourth7
11 1510353747416681 0 29946 29948 14 TEST_THR_1 dbg . tidx=1 loop=1 of 2 tid=29948 this is the third long message - third0 third1 third2 third3 third4 third5 third6 third7 third8 th
25 1510353747416652 29 29946 29948 14 TEST_THR_1 inf . tidx=1 loop=1 of 2 tid=29948 this is the second long message - second0 second1 second2 second3 second4 second5 second6 second7
29 1510353747416621 31 29946 29948 14 TEST_THR_1 inf . tidx=1 loop=1 of 2 tid=29948 I need to test longer messages. They need to be about 256 characters - longer than the circular me
cpu="0"
min 0
max 31
tot 90
ave 10
cnt 9
$ tshow | grep TEST_THR_0 | tdelta -d 1 -stats
30 1510353747416617 0 29946 29947 13 TEST_THR_0 d05 . tidx=0 loop=2 of 2 tid=29947 - extra, if enabled
31 1510353747416617 0 29946 29947 13 TEST_THR_0 d04 . tidx=0 loop=2 of 2 tid=29947 this is the fourth long message - fourth0 fourth1 fourth2 fourth3 fourth4 fourth5 fourth6 fourth7
32 1510353747416616 1 29946 29947 13 TEST_THR_0 dbg . tidx=0 loop=2 of 2 tid=29947 this is the third long message - third0 third1 third2 third3 third4 third5 third6 third7 third8 th
33 1510353747416616 0 29946 29947 13 TEST_THR_0 inf . tidx=0 loop=2 of 2 tid=29947 this is the second long message - second0 second1 second2 second3 second4 second5 second6 second7
34 1510353747416616 0 29946 29947 13 TEST_THR_0 inf . tidx=0 loop=2 of 2 tid=29947 I need to test longer messages. They need to be about 256 characters - longer than the circular me
35 1510353747416616 0 29946 29947 13 TEST_THR_0 d05 . tidx=0 loop=1 of 2 tid=29947 - extra, if enabled
36 1510353747416615 1 29946 29947 13 TEST_THR_0 d04 . tidx=0 loop=1 of 2 tid=29947 this is the fourth long message - fourth0 fourth1 fourth2 fourth3 fourth4 fourth5 fourth6 fourth7
37 1510353747416615 0 29946 29947 13 TEST_THR_0 dbg . tidx=0 loop=1 of 2 tid=29947 this is the third long message - third0 third1 third2 third3 third4 third5 third6 third7 third8 th
38 1510353747416614 1 29946 29947 13 TEST_THR_0 inf . tidx=0 loop=1 of 2 tid=29947 this is the second long message - second0 second1 second2 second3 second4 second5 second6 second7
39 1510353747416612 2 29946 29947 13 TEST_THR_0 inf . tidx=0 loop=1 of 2 tid=29947 I need to test longer messages. They need to be about 256 characters - longer than the circular me
cpu="0"
min 0
max 2
tot 5
ave 0.5555555
cnt 9