Trace Event Logging

Introduction

A realtime system consisting of multiple communicating programs represents a complex and dynamic environment. Trace events provide a mechanism to help detect hardware and software faults within such a system. They can also reveal the dynamics of the system as a whole, including profiles of kernel operation.

Trace events are emitted by code within the system to make visible internal conditions and states at key places. By examining the trace events emitted by the system, developers can gain a picture of the system's health and flow.

QNX/Neutrino defines two classes of trace events:

  • trace exception events - log unexpected or error conditions
  • kernel profile events - log the natural operation of the kernel

Trace exception events

These low-bandwidth events log unexpected or error conditions in the kernel or user applications. Each trace exception is assigned a severity code as follows:

SeverityDescription
_TRACE_HW_SEVERITY3 Unexpected non-recoverable hardware fault
_TRACE_HW_SEVERITY2 Unexpected recoverable hardware fault
_TRACE_HW_SEVERITY1 Expected hardware error
_TRACE_HW_SEVERITY0 Hardware information/testing use
_TRACE_SW_SEVERITY3 Unexpected non-recoverable software fault
_TRACE_SW_SEVERITY2 Unexpected recoverable software fault
_TRACE_SW_SEVERITY1 Expected software error
_TRACE_SW_SEVERITY0 Software information/testing use

Trace exceptions provide a software trace of problems that can help diagnose the reason for a software or hardware failure. The kernel and all shipped resource managers and drivers contain code to emit trace exceptions events. This code within the drivers can often be used to detect and replace marginal hardware before it fails.

For example, the following events could be logged:

  • a parity error on a serial port
  • a network out-of-window collision
  • a failure to allocate a memory buffer
  • an inconsistent software data structure

Trace event structure

Trace events consist of a 32-bit code followed by a timestamp and data. The code is broken down into a 24-bit major code and an 8-bit minor code.


fig: images/traccode.gif


Major and minor code breakdown of a 32-bit trace code.

 

The kernel, resource managers, and drivers are all assigned their own major code. OEMs and independent software vendors may request major codes that are assigned by QNX Software Systems. Each minor code is local to a major code and controlled by the owner of the major code.

Emitting an exception event

A set of convenience macros for emitting trace exception events is provided.

FunctionDescription
Trace0() Trace exception event, no args, no buffer
Trace0b() Trace exception event, no args, buffer
Trace1() Trace exception event, 1 args, no buffer
Trace1b() Trace exception event, 1 args, buffer
... ...
Trace6() Trace exception event, 6 args, no buffer
Trace6b() Trace exception event, 6 args, buffer

These macros invoke the kernel call TraceEvent(). The kernel call itself doesn't save the passed data. Instead, it checks to see if an optional trace event logger has been installed and if so executes an upcall into it.

A process wishing to act as a trace event logger uses the standard InterruptAttach() kernel call attaching to the special interrupt _NTO_INTR_TRACE. If no handlers have been installed, the event is discarded. A standard logger called Trace is provided with Neutrino.

Placing the code that logs the event outside the kernel has several benefits:

  • Systems that don't wish to save the trace events won't have to incur any code to do so. For instance, a consumer electronics device with no storage probably wouldn't be in any position to save them anyway.
  • The logger can be custom designed for the characteristics of the system. There may be an area of battery-backed RAM in which the events may be saved and will survive a crash or power failure.
  • Loggers can be written that watch for certain values and take special action when they occur. This could be as simple as popping up a message dialog on a user interface or as complex as a nuclear reactor shutdown.

Trace resource manager

QNX/Neutrino is shipped with a simple trace event handler implemented as a resource manager. The Trace program attaches to the trace event interrupt to catch trace events and makes them available for reading on the device /dev/trace. This allows applications to read the events without any special calls by simply calling open(), read(), and close().

Multiple processes may open /dev/trace at the same time, each with its own seek point within the trace event data. Reading the data doesn't remove it. The buffer may be cleared within a program by calling truncate() or unlink().

Events are maintained in a circular buffer that may be configured as small as 1K or as large as 2G. When the buffer fills, new events replace the oldest events. You can save the events to disk or transfer them over a communication line by opening /dev/trace and reading and saving the events as they occur. As a convenience, Trace provides a -l ("el") option that will create a separate thread of execution within Trace to perform this function:

 

Trace -l /logs/trace &

Printing trace events

The traceinfo utility is provided to print the contents of the in-memory trace buffer in a user-friendly way. The utility attempts to open files ending in .fmt (for formatting information) in the /usr/trace directory. This allows third parties and OEMs to provide formatting information for their own custom trace exception events without having to modify traceinfo.

CommandDescription
traceinfo Print in-memory trace buffers
traceinfo -c Print then clear in-memory trace buffers

Kernel profiling

Kernel profile events log the natural operation of the kernel. These high-bandwidth events are placed in the major execution paths within the kernel. These calls will cause a noticeable increase in code size and a measurable decrease in performance. Kernel profiles can be logged for all kernel calls and interrupts.

For example, the following events could be logged:

  • a timer is created
  • a timer is armed
  • a timer fires
  • the effect on a thread of the timer's firing

The major problem here is that significant events may be drowned in all the information logged. Today's processors can log megabytes of data on active systems in just a few seconds.

To limit the data, each kernel profile is represented by a single bit in a very wide bitmap that disables logging of the event.

 


fig: images/evenmask.gif


A kernel profile is represented by a single bit in a wide bitmap that can disable event logging.

 

Through careful selection of the kernel-profile-bitmask, it's possible to screen out high-bandwidth, but non-relevant events when producing a log for later offline analysis.

Emitting a profile event

The kernel uses the TraceEvent() function to log these high-bandwidth events. The function takes a code followed by a variable number of arguments as follows:

TraceEvent(int code, ...)

The code is defined as follows:


fig: images/kerevent.gif


Trace event structure.

 

The code is broken down into a number of fields. There's a 3-bit field for the number of arguments that directly follow. This allows for 0 to 7 arguments. The "p" (pointer) bit indicates that immediately after any arguments there will be a pointer and size word pointing to a buffer of data that will be appended to the data saved directly after the arguments.

The dat20 field may be used to hold a small amount of user-specified data.

There are 256 possible trace opcodes. Kernel profile events occupy the majority of these codes. The Trace*() macros described in the previous section on "Trace exception events" are built on top of the TraceEvent() function and use one 8-bit opcode equal to _TRACE_EXC. In this case, the first argument is reserved to hold a 32-bit trace code.


Note: Although trace exceptions are supported in the initial release (1.0) of Neutrino, kernel profiling will be instrumented in a special versionof the kernel as part of a future release of QNX/Neutrino. In order to keep the normal runtime kernel small and fast, it isn't instrumented to support profiling.

While the instrumented kernel with profiling will typically be used by developers who are analyzing their system, this kernel is functionally equivalent to the non-instrumented kernel and is suitable for target systems that can tolerate a 15% increase in code size and a 25% decrease in performance.