Tracing multithreaded programs

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,, contains the tracing routines. To obtain trace data, the application must be linked to instead of 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 files

Trace data is collected for each LWP and stored in a separate file, by default in the current working directory. The files are named:


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 SCO OpenServer tools, such as awk(C), sort(C), and sed(C).

Format of the trace data files

Each line in the files is a trace record in the following format:


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(F) manual page.

The thread_trace(F) 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.

Merging trace files

The individual trace files for each LWP will already be sorted chronologically. The following use of sort(C) 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.

Using trace file data

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.

   awk '
   BEGIN { FS=":"
   FILENAME == ARGV[1] {
   {	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:


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

where 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.

You can write additional awk scripts and sort commands to further consolidate your data as needed to analyze the behavior of your application.

Next topic: Examples
Previous topic: Debugging multithreaded programs

© 2005 The SCO Group, Inc. All rights reserved.
SCO OpenServer Release 6.0.0 -- 02 June 2005