Using traceprinter and interpreting the output

The simplest way to turn the tracing data into a form that you can analyze is to pass the .kev file through traceprinter. For details, see its entry in the Utilities Reference.

Let's take a look at an example of the output from traceprinter. This is the output from Gathering all events from all classes in the Tutorials chapter.

The output starts with some information about how you ran the trace:

TRACEPRINTER version 1.02
TRACEPARSER LIBRARY version 1.02
 -- HEADER FILE INFORMATION -- 
       TRACE_FILE_NAME:: all_classes.kev
            TRACE_DATE:: Wed Jun 24 10:52:58 2009
       TRACE_VER_MAJOR:: 1
       TRACE_VER_MINOR:: 01
   TRACE_LITTLE_ENDIAN:: TRUE
        TRACE_ENCODING:: 16 byte events
       TRACE_BOOT_DATE:: Tue Jun 23 11:47:46 2009
  TRACE_CYCLES_PER_SEC:: 736629000
         TRACE_CPU_NUM:: 1
         TRACE_SYSNAME:: QNX
        TRACE_NODENAME:: localhost
     TRACE_SYS_RELEASE:: 6.4.1
     TRACE_SYS_VERSION:: 2009/05/20-17:35:56EDT
         TRACE_MACHINE:: x86pc
     TRACE_SYSPAGE_LEN:: 2264
TRACE_TRACELOGGER_ARGS:: tracelogger -d1 -n 3 -f all_classes.kev

The next section includes information about all the processes in existence when the trace started:

 -- KERNEL EVENTS -- 
t:0x4f81e320 CPU:00 CONTROL: BUFFER sequence = 33, num_events = 714
t:0x4f81e320 CPU:00 CONTROL :TIME msb:0x000037b0 lsb(offset):0x4f81e014
t:0x4f82017a CPU:00 PROCESS :PROCCREATE_NAME
                      ppid:0
                       pid:1
                      name:proc/boot/procnto-smp-instr
t:0x4f820f9a CPU:00 THREAD  :THCREATE      pid:1 tid:1
t:0x4f821358 CPU:00 THREAD  :THREADY       pid:1 tid:1 
t:0x4f821698 CPU:00 THREAD  :THCREATE      pid:1 tid:2
t:0x4f821787 CPU:00 THREAD  :THRECEIVE     pid:1 tid:2 
t:0x4f8219ca CPU:00 THREAD  :THCREATE      pid:1 tid:3
t:0x4f821ac6 CPU:00 THREAD  :THRECEIVE     pid:1 tid:3 
t:0x4f821c94 CPU:00 THREAD  :THCREATE      pid:1 tid:4
t:0x4f821d90 CPU:00 THREAD  :THRECEIVE     pid:1 tid:4 
t:0x4f821f6c CPU:00 THREAD  :THCREATE      pid:1 tid:5
t:0x4f82205b CPU:00 THREAD  :THRECEIVE     pid:1 tid:5 
t:0x4f8222aa CPU:00 THREAD  :THCREATE      pid:1 tid:7
t:0x4f822399 CPU:00 THREAD  :THRECEIVE     pid:1 tid:7 
t:0x4f8225bd CPU:00 THREAD  :THCREATE      pid:1 tid:8
t:0x4f8226ac CPU:00 THREAD  :THRECEIVE     pid:1 tid:8 
t:0x4f8228ca CPU:00 THREAD  :THCREATE      pid:1 tid:10
t:0x4f8229b9 CPU:00 THREAD  :THRECEIVE     pid:1 tid:10 
t:0x4f822b7d CPU:00 THREAD  :THCREATE      pid:1 tid:11
t:0x4f822c6c CPU:00 THREAD  :THRECEIVE     pid:1 tid:11 
t:0x4f822dd7 CPU:00 THREAD  :THCREATE      pid:1 tid:12
t:0x4f822ec6 CPU:00 THREAD  :THRECEIVE     pid:1 tid:12 
t:0x4f8230ac CPU:00 THREAD  :THCREATE      pid:1 tid:15
t:0x4f82319b CPU:00 THREAD  :THRECEIVE     pid:1 tid:15 
t:0x4f8233ca CPU:00 THREAD  :THCREATE      pid:1 tid:20
t:0x4f8234b9 CPU:00 THREAD  :THRECEIVE     pid:1 tid:20 
t:0x4f823ad0 CPU:00 PROCESS :PROCCREATE_NAME
                      ppid:1
                       pid:2
                      name:sbin/tinit
t:0x4f823f38 CPU:00 THREAD  :THCREATE      pid:2 tid:1
t:0x4f82402e CPU:00 THREAD  :THREPLY       pid:2 tid:1 
t:0x4f82447d CPU:00 PROCESS :PROCCREATE_NAME
                      ppid:2
                       pid:4099
                      name:proc/boot/pci-server
t:0x4f824957 CPU:00 THREAD  :THCREATE      pid:4099 tid:1
t:0x4f824a4d CPU:00 THREAD  :THRECEIVE     pid:4099 tid:1 
t:0x4f824ff8 CPU:00 PROCESS :PROCCREATE_NAME
                      ppid:2
                       pid:4100
                      name:proc/boot/slogger2

You can suppress this initial information by passing the _NTO_TRACE_STARTNOSTATE command to TraceEvent(), but you'll likely need the information (including process IDs and thread IDs) to make sense out of the actual trace data.

The sample above shows the creation and naming of the instrumented kernel procnto-smp-instr (process ID 1) and its threads (thread ID 1 is the idle thread), followed by tinit (process ID 2), pci-server, and slogger2. Some of these are the processes that were launched when you booted your system.

This continues for a while, culminating in the creation of the tracelogger process and our own program, all_classes (process ID 1511472):

t:0x4f852aa8 CPU:00 PROCESS :PROCCREATE_NAME
                      ppid:426015
                       pid:1507375
                      name:usr/sbin/tracelogger
t:0x4f853360 CPU:00 THREAD  :THCREATE      pid:1507375 tid:1
t:0x4f853579 CPU:00 THREAD  :THRECEIVE     pid:1507375 tid:1 
t:0x4f85392a CPU:00 THREAD  :THCREATE      pid:1507375 tid:2
t:0x4f853a19 CPU:00 THREAD  :THSIGWAITINFO pid:1507375 tid:2 
t:0x4f853d96 CPU:00 PROCESS :PROCCREATE_NAME
                      ppid:426022
                       pid:1511472
                      name:./all_classes
t:0x4f854048 CPU:00 THREAD  :THCREATE      pid:1511472 tid:1
t:0x4f854140 CPU:00 THREAD  :THRUNNING     pid:1511472 tid:1 

Next is the exit from our program's call to TraceEvent():

t:0x4f854910 CPU:00 KER_EXIT:TRACE_EVENT/01 ret_val:0x00000000 empty:0x00000000

Why doesn't the trace doesn't include the entry to TraceEvent()? Well, tracelogger didn't log anything until our program told it to—by calling TraceEvent()!

So far, so good, but now things get more complicated:

t:0x4f856aac CPU:00 KER_CALL:THREAD_DESTROY/47 tid:-1 status_p:0
t:0x4f857dca CPU:00 KER_EXIT:THREAD_DESTROY/47 ret_val:0x00000030 empty:0x00000000
t:0x4f8588d3 CPU:00 KER_CALL:THREAD_DESTROYALL/48 empty:0x00000000 empty:0x00000000
t:0x4f858ed7 CPU:00 THREAD  :THDESTROY     pid:1511472 tid:1
t:0x4f8598b9 CPU:00 THREAD  :THDEAD        pid:1511472 tid:1 
t:0x4f859c4c CPU:00 THREAD  :THRUNNING     pid:1 tid:1 

You can see that a thread is being destroyed, but which one? The tid of -1 refers to the current thread, but which process does it belong to? As mentioned earlier, most of the events don't indicate what caused the event to occur; you have to infer from a previous thread-running event. In this case, it's our own program (process ID 1511472) that's ending; it starts the tracing, and then exits. Thread 1 of procnto-smp-instr (the idle thread) runs.

The trace continues like this:

t:0x4f85c6e3 CPU:00 COMM    :SND_PULSE_EXE scoid:0x40000002 pid:1
t:0x4f85cecd CPU:00 THREAD  :THRUNNING     pid:1 tid:12 
t:0x4f85d5ad CPU:00 THREAD  :THREADY       pid:1 tid:1 
t:0x4f85e5b3 CPU:00 COMM    :REC_PULSE     scoid:0x40000002 pid:1
t:0x4f860ee2 CPU:00 KER_CALL:THREAD_CREATE/46 func_p:f0023170 arg_p:eff6e000
t:0x4f8624c7 CPU:00 THREAD  :THCREATE      pid:1511472 tid:1
t:0x4f8625ff CPU:00 THREAD  :THWAITTHREAD  pid:1 tid:12 
t:0x4f8627b4 CPU:00 THREAD  :THRUNNING     pid:1511472 tid:1 
t:0x4f8636fd CPU:00 THREAD  :THREADY       pid:1 tid:12 
t:0x4f865c34 CPU:00 KER_CALL:CONNECT_SERVER_INFO/41 pid:0 coid:0x00000000
t:0x4f866836 CPU:00 KER_EXIT:CONNECT_SERVER_INFO/41 coid:0x00000000 info->nd:0
t:0x4f86735e CPU:00 KER_CALL:TIMER_TIMEOUT/75 timeout_flags:0x00000050 ntime(sec):30
t:0x4f868445 CPU:00 KER_EXIT:TIMER_TIMEOUT/75 prev_timeout_flags:0x00000000 otime(sec):0
t:0x4f8697d3 CPU:00 INT_ENTR:0x00000000 (0)       IP:0xf008433e
t:0x4f86a276 CPU:00 INT_HANDLER_ENTR:0x00000000 (0)       PID:126997 IP:0x080b7334 AREA:0x0812a060
t:0x4f86afa7 CPU:00 INT_HANDLER_EXIT:0x00000000 (0) SIGEVENT:NONE
t:0x4f86b304 CPU:00 INT_HANDLER_ENTR:0x00000000 (0)       PID:1 IP:0xf0056570 AREA:0x00000000
t:0x4f86ca12 CPU:00 INT_HANDLER_EXIT:0x00000000 (0) SIGEVENT:NONE
t:0x4f86cff6 CPU:00 INT_EXIT:0x00000000 (0) inkernel:0x00000f01
t:0x4f86e276 CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000000 msg:"" (0x00040116)
t:0x4f86e756 CPU:00 COMM    :SND_MESSAGE   rcvid:0x0000004f pid:159762
t:0x4f86f84a CPU:00 THREAD  :THREPLY       pid:1511472 tid:1 
t:0x4f8705dd CPU:00 THREAD  :THREADY       pid:159762 tid:1 
t:0x4f8707d4 CPU:00 THREAD  :THRUNNING     pid:159762 tid:1 
t:0x4f870bff CPU:00 COMM    :REC_MESSAGE   rcvid:0x0000004f pid:159762
t:0x4f878b6c CPU:00 KER_CALL:MSG_REPLYV/15 rcvid:0x0000004f status:0x00000000
t:0x4f878f4b CPU:00 COMM    :REPLY_MESSAGE tid:1 pid:1511472
t:0x4f8798d2 CPU:00 THREAD  :THREADY       pid:1511472 tid:1 

The SND_PULSE_EXE event indicates that a SIGEV_PULSE was sent to the server connection ID 0x40000002 of procnto-smp-instr, but what is it, and who sent it? Thread 12 of the kernel receives it, and then surprisingly creates a new thread 1 in our process (ID 1511472), and starts chatting with it. What we're seeing here is the teardown of our process. It delivers a death pulse to the kernel, and then one of the kernel's threads receives the pulse and creates a thread in the process to clean up.

In the midst of this teardown, an interrupt occurs, its handler runs, and a message is sent to the process with ID 159762. By looking at the initial system information, we can determine that process ID 159762 is devc-pty.

Farther down in the trace is the actual death of our all_classes process:

t:0x4f8faa68 CPU:00 THREAD  :THRUNNING     pid:1 tid:20 
t:0x4f8fb09f CPU:00 COMM    :REC_PULSE     scoid:0x40000002 pid:1
t:0x4f8ff1a5 CPU:00 PROCESS :PROCDESTROY   ppid:426022 pid:1511472

As you can tell from a very short look at this trace, wading through a trace can be time-consuming, but can give you a great understanding of what exactly is happening in your system.

You can simplify your task by terminating any processes that you don't want to include in the trace, or by filtering the trace data.