Capturing Trace Data

This chapter includes:

• Overview
• Using tracelogger to control tracing
• Using TraceEvent() to control tracing

Overview

The program that captures data is the “messenger” between the instrumented kernel and the filesystem.

Possible data capture configurations.

The main function of the data-capture program is to send the buffers given to it by the instrumented kernel to an output device (which may be a file or something else). In order to accomplish this function, the program must also:

• interface with the instrumented kernel
• specify data-filtering requirements the instrumented kernel will use

You must configure the instrumented kernel before logging. The instrumented kernel configuration settings include:

• buffer allocations (size)
• which events and classes of events to log (filtering)
• whether to log the events in wide mode or fast mode

---

The instrumented kernel retains the settings, and multiple programs access a single instrumented kernel configuration. Changing the settings in one process supersedes the settings made in another.

---

We've provided tracelogger as the default data-capture utility. Although you can write your own utility, there's little need to.

You can control the capture of data via qconn (under the control of the IDE), tracelogger (from the command line), or directly from your application. All three approaches use the TraceEvent() function to control the instrumented kernel:

Controlling the capture of trace data.

For information about controlling the trace from the IDE, see the Analyzing Your System with Kernel Tracing chapter of the IDE User's Guide.

Let's look first at using tracelogger, and then we'll describe how you can use TraceEvent() to control tracing from your application.

---

Don't run more than one instance of tracelogger at a time. Similarly, don't run tracelogger and trace events under control of the IDE at the same time. On a multicore system, if the clocks on all processors aren't synchronized, then tracelogger will produce data with inconsistent timestamps, and the IDE won't be able to load the trace file. The IDE attempts to properly order the events in the trace file, and this can go awry if the timestamp data is incorrect. The traceprinter utility doesn't have any issues with such traces because it doesn't attempt to reorder the data and interpret it; it simply dumps the contents of each event.

---

Using tracelogger to control tracing

The options that you use when you start tracelogger affect the way that the instrumented kernel logs events and how tracelogger captures them. In this section, we'll look at:

• managing trace buffers
• tracelogger's modes of operation
• choosing between wide and fast modes
• filtering events
• specifying where to send the output

Managing trace buffers

You can use tracelogger's command-line options to manage the instrumented kernel's buffers, specifying:

• the number of buffers
• whether or not to preserve the buffers in shared memory, to reuse later

You can also specify the number of buffers that tracelogger itself uses.

For more information, see the entry for tracelogger in the Neutrino Utilities Reference.

tracelogger's modes of operation

You can run tracelogger in several modes — depending on how and what you want to trace — by specifying the following command-line options:

^a In daemon mode, logging starts when an application calls TraceEvent(_NTO_TRACE_START) and continues until an application calls TraceEvent(_NTO_TRACE_STOP), or until you terminate tracelogger.

^b When you terminate tracing in ring mode, tracelogger stops logging events, and then briefly restarts and stops it again so it can capture the state information that's emitted by the _NTO_TRACE_START command. This information includes the thread IDs and names of processes.

In the non-daemon modes, you configure, start, and stop the tracing from the command line. In daemon mode, your application must do everything from code, but if you also specify the -E option, tracelogger enables all events in all classes, and you can use the -F option to set up filtering.

Here's an outline of the strengths, weaknesses, and features of these modes:

---

If an application has called TraceEvent(_NTO_TRACE_START), and you then try to start tracelogger, tracelogger might fail with a “resource busy” message. To help avoid this: Start tracelogger before your application issues a _NTO_TRACE_START or _NTO_TRACE_STARTNOSTATE command. Don't leave tracing on indefinitely; be sure to issue a _NTO_TRACE_STOP after each _NTO_TRACE_START or _NTO_TRACE_STARTNOSTATE command.

---

For a full description of the tracelogger utility and its options, see its entry in the Neutrino Utilities Reference.

Choosing between wide and fast modes

By default, the instrumented kernel and tracelogger collect data in fast mode; to switch to wide mode, specify the -w option when you start tracelogger.

Filtering events

The tracelogger utility gives you some basic control over filtering by way of its -F option. This filtering is limited to excluding entire classes of events at a time; if you need a finer granularity, you'll need to use TraceEvent(), as described in the Filtering chapter in this guide.

By default, tracelogger captures all events from all classes, but you can disable the tracing of events from the classes as follows:

You can specify more than one filter by using multiple -F options. Note that you can't disable the Control or User classes with this option. For more information about classes, see the Events and the Kernel chapter of this guide.

Specifying where to send the output

Because the ring of buffers can't hope to store a complete log of event activity for any significant amount of time, the tracebuffer must be handed off to a data-capture program. Normally the data-capture program pipes the information to either an output device or a file.

By default, the tracelogger utility saves the output in the binary file /dev/shmem/tracebuffer.kev, but you can use the -f option to specify a different path. The .kev extension is short for “kernel events”; you can use a different extension, but the IDE recognizes .kev and automatically uses the System Profiler to open such files.

You can also map the file in shared memory (-M), but you must then also specify the maximum size for the file (-S).

Using TraceEvent() to control tracing

You don't have to use tracelogger to control all aspects of tracing; you can call TraceEvent() directly — which (after all) is what tracelogger does. Using TraceEvent() to control tracing means a bit more work for you, but you have much more control over specific details.

You could decide not to use tracelogger at all, and use TraceEvent() exclusively, but you'd then have to manage the buffers, collect the trace data, and save it in the appropriate form, which could be a significant amount of work.

In practical terms you'll likely use tracelogger and TraceEvent() together. For example, you might run tracelogger in daemon mode, to take advantage of its management of the trace data, but call TraceEvent() to control exactly which events to trace.

The TraceEvent() kernel call takes a variable number of arguments. The first is always a command and determines what (if any) additional arguments are required.

In this section, we'll discuss:

• managing trace buffers
• modes of operation
• filtering events
• choosing between wide and fast modes
• inserting trace events

For reference information about TraceEvent(), see the QNX Neutrino Library Reference.

Managing trace buffers

As mentioned above, you can use TraceEvent() to manage the instrumented kernel's buffers, but it's probably easier to run tracelogger in daemon mode and let it look after the buffers. Nevertheless, here's a summary of how to do it with TraceEvent():

• To allocate the buffers, use the _NTO_TRACE_ALLOCBUFFER command, specifying the number of buffers and a pointer to a location where TraceEvent() can store the physical address of the beginning of the ring of allocated trace buffers:

  TraceEvent(_NTO_TRACE_ALLOCBUFFER, uint bufnum, void** paddr);
    

  Allocated trace buffers can store 1024 simple trace events.

  ---

  Your application must run as root in order to use this command.

  ---

  Once you've allocated the buffers, you can use mmap_device_memory() to map the buffers into your process's address space and get their virtual address. For example:

  paddr_t paddr;
  tracebuf_t *kbufs;
  
  ret = TraceEvent(_NTO_TRACE_ALLOCBUFFER, num_buffers, &paddr);
  if( ret == -1 )
  {
    // Handle the error.
  }
  
  kbufs = mmap_device_memory(0, num_buffers * sizeof(tracebuf_t), PROT_READ | PROT_WRITE,
                             0, paddr );
  if( kbufs == MAP_FAILED )
  {
    // Handle the error.
  }

  Then you can use InterruptHookTrace() to register a handler for the _NTO_HOOK_TRACE synthetic interrupt that the instrumented kernel raises as each buffer becomes full.

• To free the buffers, use the _NTO_TRACE_DEALLOCBUFFER command. It doesn't take any additional arguments:

  TraceEvent(_NTO_TRACE_DEALLOCBUFFER);
    

  All events stored in the trace buffers are lost.

• To flush the buffer, regardless of the number of trace events it contains, use the _NTO_TRACE_FLUSHBUFFER command:

  TraceEvent(_NTO_TRACE_FLUSHBUFFER);
    

• To get the number of simple trace events that are currently stored in the trace buffer, use the _NTO_TRACE_QUERYEVENTS command:

  num_events = TraceEvent(_NTO_TRACE_QUERYEVENTS);
    

For examples of some of these commands, see “Data-capture program” in the “Sample Programs” appendix.

Modes of operation

TraceEvent() doesn't support the different modes of operation that tracelogger does; your application has to indicate when to start tracing, how long to trace for, and so on:

• To choose linear or ring mode, use the _NTO_TRACE_SETLINEARMODE or _NTO_TRACE_SETRINGMODE command:

  TraceEvent(_NTO_TRACE_SETLINEARMODE);
  TraceEvent(_NTO_TRACE_SETRINGMODE);
    

  As described earlier in this chapter, in ring mode the kernel stores all events in the ring of buffers without flushing them. In linear mode (the default), every filled-up buffer is captured and flushed immediately.

  ---

  _NTO_TRACE_SETLINEARMODE and _NTO_TRACE_SETRINGMODE cause the trace buffers to be cleared, so you should use these commands before you start tracing.

  ---

• To start tracing, use the _NTO_TRACE_START or _NTO_TRACE_STARTNOSTATE command:

  TraceEvent(_NTO_TRACE_START);
  TraceEvent(_NTO_TRACE_STARTNOSTATE);

  These commands are similar, except that _NTO_TRACE_STARTNOSTATE suppresses the initial system state information (which includes thread IDs and the names of processes). This information is overwritten when the kernel reuses the buffer; if you're logging events in ring mode, you can make sure you capture the process names by issuing an _NTO_TRACE_START command followed by _NTO_TRACE_STOP after you've finished tracing.

• To stop tracing, use the _NTO_TRACE_STOP command:

  TraceEvent(_NTO_TRACE_STOP);
    

  You can decide whether to trace until you've gathered a certain quantity of data, trace for a certain length of time, or trace only during an operation that's of particular interest to you. After stopping the trace, you should flush the buffer by calling:

  TraceEvent(_NTO_TRACE_FLUSHBUFFER);
    

---

If an application has called TraceEvent(_NTO_TRACE_START), and you then try to start tracelogger, tracelogger might fail with a “resource busy” message. To help avoid this: Start tracelogger before your application issues a _NTO_TRACE_START or _NTO_TRACE_STARTNOSTATE command. Don't leave tracing on indefinitely; be sure to issue a _NTO_TRACE_STOP after each _NTO_TRACE_START or _NTO_TRACE_STARTNOSTATE command.

---

Filtering events

You can select events in an additive or subtractive manner; you can start with no events, and then add specific classes or events, or you can start with all events, and then exclude specific ones. We'll discuss using TraceEvent() to filter events in the Filtering chapter.

Choosing between wide and fast modes

TraceEvent() gives you much finer control over wide and fast mode than you can get with tracelogger, which can simply set the mode for all events in all traced classes. Using TraceEvent(), you can set fast and wide mode for all classes, a specific class, or a specific event in a class:

• To set the mode for all classes, use the _NTO_TRACE_SETALLCLASSESWIDE or _NTO_TRACE_SETALLCLASSESFAST command. These commands don't require any additional arguments:

  TraceEvent( _NTO_TRACE_SETALLCLASSESWIDE );
  TraceEvent( _NTO_TRACE_SETALLCLASSESFAST );
    

• To set the mode for all events in a class, use the _NTO_TRACE_SETCLASSFAST or _NTO_TRACE_SETCLASSWIDE command. These commands require a class as an additional argument:

  TraceEvent(_NTO_TRACE_SETCLASSFAST, int class);
  TraceEvent(_NTO_TRACE_SETCLASSWIDE, int class);
    

  For example:

  TraceEvent(_NTO_TRACE_SETCLASSWIDE, _NTO_TRACE_KERCALLENTER);
    

• To set the mode for a specific event in a class, use the _NTO_TRACE_SETEVENTFAST or _NTO_TRACE_SETEVENTWIDE command, specifying the class, followed by the event:

  TraceEvent(_NTO_TRACE_SETEVENTFAST, int class, int event)
  TraceEvent(_NTO_TRACE_SETEVENTWIDE, int class, int event)
    

  For example:

  TraceEvent(_NTO_TRACE_SETEVENTFAST, _NTO_TRACE_KERCALLENTER,
             __KER_INTERRUPT_ATTACH);
    

Inserting trace events

You can even use TraceEvent() to insert your own events into the trace data. You can call TraceEvent() directly (see below), but it's much easier to use the following convenience functions:

trace_func_enter()

Insert a trace event for the entry to a function

trace_func_exit()

Insert a trace event for the exit from a function

trace_here()

Insert a trace event for the current address

trace_logb()

Insert a user combine trace event

trace_logbc()

Insert a trace event of an arbitrary class and type with arbitrary data

trace_logf()

Insert a user string trace event

trace_logi()

Insert a user simple trace event

trace_nlogf()

Insert a user string trace event, specifying a maximum string length

trace_vnlogf()

Insert a user string trace event, using a variable argument list

If you want to call TraceEvent() directly, use one of the following commands:

• _NTO_TRACE_INSERTCCLASSEVENT
• _NTO_TRACE_INSERTCUSEREVENT
• _NTO_TRACE_INSERTEVENT
• _NTO_TRACE_INSERTSCLASSEVENT
• _NTO_TRACE_INSERTSUSEREVENT
• _NTO_TRACE_INSERTUSRSTREVENT

For more information, see the entry for TraceEvent() in the QNX Neutrino Library Reference.