traceprinter

Updated: April 19, 2023

Display the contents of the instrumented kernel trace file

Syntax:

traceprinter [-nv] [-f file] [-o out_file] [-p fmt]

Runs on:

QNX Neutrino, Linux, Mac, Microsoft Windows

Options:

-f file
The filename of the file that stores the trace information to be displayed. The default is /dev/shmem/tracebuffer.kev.
-n
Remove newline characters from printed argument lines.
-o out_file
The name of the file in which to store the data. By default, traceprinter sends its output to stdout.
-p fmt
(QNX Neutrino 7.0 or later) Specify the information that you want displayed. The fmt is similar to the string you'd pass to printf() and may include the following:
  • %% — a literal percent sign
  • %c — 64-bit cycle count
  • %C — CPU
  • %e — event ID
  • %t — microsecond timestamp
  • %Z — event class
  • %z — event subtype

They follow the same syntax as printf() format specifiers with one addition: a negative precision truncates the leading characters instead of the trailing characters. For example, the default string is "t:0x%08c CPU:%02C %-16Z:%-18z" and gives output like this:

t:0x4be9a514 CPU:01 SYSTEM          :

If you specify "e:%06e t:%014t c:0x%010c CPU:%02C %-16Z:%-18z" for fmt, the output looks like this:

e:0000000010 t:0.000.016us c:0x004be9a514 CPU:01 SYSTEM          :
-v
Display detailed information.

Description:

The traceprinter utility displays the contents of a trace file generated by tracelogger. The utility parses the linearly stored time events stored in the named trace file and sends the resulting formatted stream to standard output (or to the file identified by the -o option).

The formatted stream looks like this:

t:clk_time CPU:cpu [class: event: [P1: [P2: [P3: ... [Pn:]]]]]

The stream always shows the clk_time and cpu variables; the variables in brackets are optional.

clk_time
The time offset in CPU clock cycles when the trace event was registered. The 64-bit variable is broken into two 32-bit hexadecimal numbers (msb and lsb). Apart from at the start of the trace and when the lsb rolls over, only the lsb number is shown.
cpu
A 2-digit decimal number representing the CPU that registered the event. The variable is always 00 unless you have more than one CPU in your system: if you have four CPUs, the CPU numbers range from 00 to 03. The CPU numbers are assigned to particular CPUs during initialization, when the startup programs probe the system (see procnto*).
Optional variables
The other variables are optional, depending on the tracing information logged. The class and event variables are followed by parameter variables, the number and type of parameters depend on the associated class/event pair and whether tracelogger used the fast or wide emitting mode. Each trace line contains one class, one or no event, and one or more parameter variables. The table below explains which parameters are shown for each combination of class and event.
Class Event Parameters
CONTROL TIME
  • P1: msb
  • P2: lsb (offset)
INT_ENTR, INT_EXIT Interrupt number in hexadecimal (and decimal) notation
  • P1: inkernel
THREAD
  • THDEAD
  • THRUNNING
  • THREADY
  • THSTOPPED
  • THSEND
  • THRECEIVE
  • THREPLY
  • THSTACK
  • THWAITTHREAD
  • THWAITPAGE
  • THSIGSUSPEND
  • THSIGWAITINFO
  • THNANOSLEEP
  • THMUTEX
  • THCONDVAR
  • THJOIN
  • THINTR
  • THSEM
  • THWAITCTXN
  • THNET_SEND
  • THNET_REPLY
  • THCREATE
  • THDESTROY
  • P1: PID
  • P2: thread ID
VTHREAD
  • VTHDEAD
  • VTHRUNNING
  • VTHREADY
  • VTHSTOPPED
  • VTHSEND
  • VTHRECEIVE
  • VTHREPLY
  • VTHSTACK
  • VTHWAITVTHREAD
  • VTHWAITPAGE
  • VTHSIGSUSPEND
  • VTHSIGWAITINFO
  • VTHNANOSLEEP
  • VTHMUTEX
  • VTHCONDVAR
  • VTHJOIN
  • VTHINTR
  • VTHSEM
  • VTHWAITCTXN
  • VTHNET_SEND
  • VTHNET_REPLY
  • VTHCREATE
  • VTHDESTROY
  • P1: PID
  • P2: vthread ID
PROCESS
  • PROCCREATE
  • PROCCREATE_NAME
  • PROCDESTROY
  • PROCDESTROY_NAME
  • P1: parent PID
  • P2: PID
  • P3: process name (optional)
KER_CALL Kernel call name
  • P1: kernel call number
  • P2, P3, ... Pn: kernel call arguments
KER_EXIT Kernel call name
  • P1: kernel call number
  • P2, P3, ... Pn: kernel call return values

The number of arguments and return values depends on the event and whether the trace file was produced using fast or wide tracing mode. For more information, see the Current Trace Events and Data appendix of the System Analysis Toolkit User's Guide.

Examples:

Here's an example of the first few lines of output from traceprinter:

TRACEPRINTER version 0.94
 -- HEADER FILE INFORMATION -- 
       TRACE_FILE_NAME:: /scratch/quadlog
            TRACE_DATE:: Fri Jun  8 13:14:40 2001
       TRACE_VER_MAJOR:: 0
       TRACE_VER_MINOR:: 96
   TRACE_LITTLE_ENDIAN:: TRUE
        TRACE_ENCODING:: 16 byte events
       TRACE_BOOT_DATE:: Fri Jun  8 04:31:05 2001
  TRACE_CYCLES_PER_SEC:: 400181900
         TRACE_CPU_NUM:: 4
         TRACE_SYSNAME:: QNX
        TRACE_NODENAME:: x86quad.gp.qa
     TRACE_SYS_RELEASE:: 6.1.0
     TRACE_SYS_VERSION:: 2001/06/04-14:07:56
         TRACE_MACHINE:: x86pc
     TRACE_SYSPAGE_LEN:: 2440
 -- KERNEL EVENTS -- 
t:0x1310da15 CPU:01 CONTROL :TIME msb:0x0000000f, lsb(offset):0x1310d81c
t:0x1310e89d CPU:01 PROCESS :PROCCREATE_NAME
                      ppid:0
                       pid:1
                      name:./procnto-smp-instr
t:0x1310eee4 CPU:00 THREAD  :THCREATE      pid:1 tid:1
t:0x1310f052 CPU:00 THREAD  :THRUNNING     pid:1 tid:1
t:0x1310f144 CPU:01 THREAD  :THCREATE      pid:1 tid:2
t:0x1310f201 CPU:01 THREAD  :THREADY       pid:1 tid:2
t:0x1310f32f CPU:02 THREAD  :THCREATE      pid:1 tid:3
t:0x1310f3ec CPU:02 THREAD  :THREADY       pid:1 tid:3
t:0x1310f52d CPU:03 THREAD  :THCREATE      pid:1 tid:4
t:0x1310f5ea CPU:03 THREAD  :THRUNNING     pid:1 tid:4
t:0x1310f731 CPU:02 THREAD  :THCREATE      pid:1 tid:5
t:0x1310f7ee CPU:02 THREAD  :THRECEIVE     pid:1 tid:5
t:0x1310f921 CPU:03 THREAD  :THCREATE      pid:1 tid:6
t:0x1310f9de CPU:03 THREAD  :THRECEIVE     pid:1 tid:6
t:0x1310fb0b CPU:01 THREAD  :THCREATE      pid:1 tid:7
t:0x1310fbc8 CPU:01 THREAD  :THRECEIVE     pid:1 tid:7
t:0x1310fd1d CPU:02 THREAD  :THCREATE      pid:1 tid:8
t:0x1310fdda CPU:02 THREAD  :THRECEIVE     pid:1 tid:8
t:0x1310ff35 CPU:02 THREAD  :THCREATE      pid:1 tid:9
t:0x1310fff2 CPU:02 THREAD  :THRECEIVE     pid:1 tid:9
t:0x131100cc CPU:01 THREAD  :THCREATE      pid:1 tid:10
t:0x13110189 CPU:01 THREAD  :THRECEIVE     pid:1 tid:10
t:0x131102d5 CPU:03 THREAD  :THCREATE      pid:1 tid:11
t:0x13110392 CPU:03 THREAD  :THRECEIVE     pid:1 tid:11
t:0x1311084d CPU:01 PROCESS :PROCCREATE_NAME
                      ppid:1
                       pid:2
                      name:proc/boot/slogger2
t:0x13110c13 CPU:03 THREAD  :THCREATE      pid:2 tid:1
t:0x13110ce0 CPU:03 THREAD  :THRECEIVE     pid:2 tid:1

Exit status:

-1
An error occurred.

Errors:

Severe errors cause traceprinter to terminate; noncatastrophic errors are displayed in verbose mode (if the -v option is set).

Caveats:

You must run tracelogger before running traceprinter. The tracelogger utility creates an event file containing trace data; traceprinter parses and prints the data in this file.