|
|
The Threads Library provides a mechanism for tracing library events. Calls to all Threads Library routines can be traced. Significant information, such as arguments, return values, lock contention, and duration of execution is recorded. Using tracing facilities, you can find the latency time for obtaining a lock, for example, or the number of acquisition attempts on a lock.
To avoid a performance penalty on the Threads Library,
a separate library, libthreadT.so, contains the tracing routines.
To obtain trace data,
the application must be linked to libthreadT.so
instead of libthread.so.
Use the following command:
cc [options] -Kthread file [-lother_libraries]
Note that the Threads Library must be the last library on the line.
Trace data is collected for each LWP
and stored in a separate file,
by default in the current working directory.
The files are named:
tr.xxxxxxx.yyy
where xxxxxxx is the seven least significant hexadecimal digits of the process ID associated with the LWP and yyy is the three least significant hexadecimal digits of the LWP ID.
When a traced application completes execution, one trace file will exist for each LWP that existed in the life of that application. The logical way to begin to use this data is to merge all the trace files into one file with all events sorted chronologically, by thread ID, or by event. Then you can use tools to summarize the data in useful ways.
Because trace output files have not yet been standardized, no tools are provided to analyze these files, but you can construct your own using standard UnixWare tools, such as awk(1), sort(1), and sed(1).
Each line in the files is a trace record in the following format:
time1:time2:lwpid:pid:tid:event1:event2:which:a1:a2:a3:a4:a5
The meaning of each field in the record is shown
in the following table:
Meaning of trace record fields
| Field | Meaning |
|---|---|
| time1 | current time in seconds |
| time2 | current time in nanoseconds |
| lwpid | LWP ID of calling thread |
| pid | process ID of calling thread |
| tid | thread ID of calling thread |
| event1 | general category of event (type of routine called) |
| event2 | specific event (name of routine called) |
| which |
0 for a single record associated with this event
1 for the first of two records 2 for the second of two records |
| a1 | depends on event |
| a2 | depends on event |
| a3 | depends on event |
| a4 | depends on event |
| a5 | depends on event |
The first two fields record the time, the next three fields record information about the caller, the next three fields identify the event (the routine that was called), and the remaining fields record specific details about the event, such as the arguments passed to the routine in question.
Further details about the contents of trace data files are given on the thread_trace(4) manual page.
The thread_trace(4) manual page also describes environment variables that can be set to change the default trace data collection. For example, you can specify a subset of events to trace or specify the directory where trace files should be created.
The individual trace files for each LWP
will already be sorted chronologically.
The following use of
sort(1)
will efficiently merge the trace
files in their current format.
sort -m -n -o mergefilename -t: +0 -4 tracefiles
where mergefilename represents the name of the merge file to be created and tracefiles represents the names of the trace files to be merged (or a regular expression that identifies them). The resulting mergefile will be sorted chronologically, and further sorted by LWP ID and process ID.
Once the trace data files are merged, translating the event category and event number fields into event names is an obvious next step. These are the sixth and seventh fields of each trace record. The following awk script will read the file specified by the first argument, translate the event fields into the associated event name, and write the output into the file specified by the second argument.
MAPPING=/tmp/tracemap.h
awk '
BEGIN { FS=":"
OFS=":"
}
FILENAME == ARGV[1] {
map[$1]=$2
next
}
{ OUT=map[$6+0"_"$7+0]
print $1" "$2" "$3" "$4" "$5" "OUT" \
"$8" "$9" "$10" "$11" "$12" "$13
}' $MAPPING $1 > $2
Note that the code on the line starting with ``print''
and the code on the line after it should all be on the same
line, and that there should be no backslash in the code.
This script assumes that tracemap.h is located in /tmp and that it maps event names to the values in the event1 and event2 fields of the trace record with entries of the form:
1_1:thr_create 1_2:thr_exit 1_3:thr_join 1_4:thr_self 1_5:thr_minstack 1_6:thr_continue 1_7:thr_suspend 1_8:thr_setconcurrency 1_9:thr_getconcurrency 1_10:thr_kill 1_11:thr_sigsetmask 1_12:thr_setscheduler 1_13:thr_getscheduler 1_14:thr_setprio 1_15:thr_getprio 1_16:thr_yield 1_17:thr_get_rr_interval 1_18:thr_keycreate 1_19:thr_keydelete 1_20:thr_setspecific 1_21:thr_getspecificwhere the number before the underscore on each line is the category number of the event and the number after the underscore on each line is the event number of the event listed on that line. See thread_trace(4). Note that there should be no whitespace in tracemap.h.2_1:mutex_init 2_2:mutex_lock 2_3:mutex_trylock 2_4:mutex_unlock 2_5:mutex_destroy
3_1:cond_init 3_2:cond_signal 3_3:cond_broadcast 3_4:cond_wait 3_5:cond_timedwait 3_6:cond_destroy
4_1:sema_init 4_2:sema_wait 4_3:sema_trywait 4_4:sema_post 4_5:sema_destroy
5_1:rwlock_init 5_2:rw_rdlock 5_3:rw_wrlock 5_4:rw_unlock 5_5:rw_tryrdlock 5_6:rw_trywrlock 5_7:rwlock_destroy
6_1:rmutex_init 6_2:rmutex_lock 6_3:rmutex_trylock 6_4:rmutex_unlock 6_5:rmutex_destroy
7_1:barrier_init 7_2:barrier_wait 7_3:barrier_destroy
8_1:_barrier_spin_init 8_2:_barrier_spin 8_3:_barrier_spin_destroy
9_1:_spin_init 9_2:_spin_lock 9_3:_spin_trylock 9_4:_spin_unlock 9_5:_spin_destroy
You can write additional awk scripts and sort commands to further consolidate your data as needed to analyze the behavior of your application.