Tutorials

This chapter leads you through some tutorials to help you learn how to use TraceEvent() to control event tracing. It includes:

Overview
The instrex.h header file
Gathering all events from all classes
Gathering all events from one class
Gathering five events from four classes
Gathering kernel calls
Event handling - simple
Inserting a user simple event

Overview

These tutorials all follow the same general procedure:

Compile the specified C program into a file of the same name, without the .c extension. You can copy the programs from this document, or you can get them from our Foundry27 website; go to http://community.qnx.com, log into your myQNX account, go to the project for the QNX Neutrino OS, and look for utils/t/traceprinter/examples.
Run the specified tracelogger command. Because we're running tracelogger in daemon mode, it doesn't start logging events until our program tells it to. This means that you don't have to rush to start your C program; the tracing waits for you.
The default number of buffers is 32, which produces a rather large file, so we'll use the -n option to limit the number of buffers to a reasonable number. Feel free to use the default, but expect a large file.
In a separate terminal window, run the compiled C program. Some examples use options.
Watch the first terminal window; a few seconds after you start your C program, tracelogger will finish running.
If you run the program, it generates its own sample result file. The “tracebuffer” files are binary files that can be interpreted only with the libtraceparser library, which the traceprinter utility uses.
If you don't want to run the program, take a look at our traceprinter output. (Note that different versions and systems will create slightly different results.)

You may include these samples in your code as long as you comply with the license agreement.

The `instrex.h` header file

To reduce repetition and keep the programs simple, we've put some functionality into a header file, instrex.h:

/*
 * $QNXLicenseC:
 * Copyright 2007, QNX Software Systems. All Rights Reserved.
 * 
 * You must obtain a written license from and pay applicable license fees to QNX 
 * Software Systems before you may reproduce, modify or distribute this software, 
 * or any work that includes all or part of this software.   Free development 
 * licenses are available for evaluation and non-commercial purposes.  For more 
 * information visit http://licensing.qnx.com or email licensing@qnx.com.
 *  
 * This file may contain contributions from others.  Please review this entire 
 * file for other proprietary rights or license notices, as well as the QNX 
 * Development Suite License Guide at http://licensing.qnx.com/license-guide/ 
 * for other information.
 * $
 */





/*
 *  instrex.h instrumentation examples - public definitions
 *
 */

#ifndef __INSTREX_H_INCLUDED

#include <errno.h>
#include <stdio.h>
#include <string.h>

/*
 * Supporting macro that intercepts and prints a possible
 * error state during calling TraceEvent(...)
 *
 * Call TRACE_EVENT(TraceEvent(...))  <=>  TraceEvent(...)
 *
 */
#define TRACE_EVENT(prog_name, trace_event) \
if((int)((trace_event))==(-1)) \
{ \
    (void) fprintf \
    ( \
     stderr, \
     "%s: line:%d function call TraceEvent() failed, errno(%d): %s\n", \
     prog_name, \
     __LINE__, \
     errno, \
     strerror(errno) \
    ); \
 \
    return (-1); \
}

/*
 * Prints error message
 */
#define TRACE_ERROR_MSG(prog_name, msg) \
    (void) fprintf(stderr,"%s: %s\n", prog_name, msg)

#define  __INSTREX_H_INCLUDED
#endif

You'll have to save instrex.h in the same directory as the C code in order to compile the programs.

Gathering all events from all classes

In our first example, we'll set up daemon mode to gather all events from all classes. Here's the source, all_classes.c:

/*
 * $QNXLicenseC:
 * Copyright 2007, QNX Software Systems. All Rights Reserved.
 * 
 * You must obtain a written license from and pay applicable license fees to QNX 
 * Software Systems before you may reproduce, modify or distribute this software, 
 * or any work that includes all or part of this software.   Free development 
 * licenses are available for evaluation and non-commercial purposes.  For more 
 * information visit http://licensing.qnx.com or email licensing@qnx.com.
 *  
 * This file may contain contributions from others.  Please review this entire 
 * file for other proprietary rights or license notices, as well as the QNX 
 * Development Suite License Guide at http://licensing.qnx.com/license-guide/ 
 * for other information.
 * $
 */





#ifdef __USAGE
%C - instrumentation example

%C  - example that illustrates the very basic use of
      the TraceEvent() kernel call and the instrumentation
      module with tracelogger in a daemon mode.

      All classes and their events are included and monitored.

      In order to use this example, start the tracelogger
      in the daemon mode as:

      tracelogger -n iter_number -d1

      with iter_number = your choice of 1 through 10

      After you start the example, the tracelogger (daemon)
      will log the specified number of iterations and then
      terminate. There are no messages printed upon successful
      completion of the example. You can view the intercepted
      events with the traceprinter utility.

      See accompanied documentation and comments within
      the sample source code for more explanations.
#endif

#include <sys/trace.h>

#include "instrex.h"

int main(int argc, char **argv)
{
    /*
     * Just in case, turn off all filters, since we
     * don't know their present state - go to the
     * known state of the filters.
     */
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_DELALLCLASSES));
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_CLRCLASSPID, _NTO_TRACE_KERCALL));
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_CLRCLASSTID, _NTO_TRACE_KERCALL));
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_CLRCLASSPID, _NTO_TRACE_THREAD));
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_CLRCLASSTID, _NTO_TRACE_THREAD));

    /*
     * Set fast emitting mode for all classes and
     * their events. 
     * Wide emitting mode could have been
     * set instead, using:
     *
     *  TraceEvent(_NTO_TRACE_SETALLCLASSESWIDE)
     */
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_SETALLCLASSESFAST));

    /*
     * Intercept all event classes
     */
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_ADDALLCLASSES));

    /*
     * Start tracing process
     *
     * During the tracing process, the tracelogger (which
     * is being executed in a daemon mode) will log all events.
     * You can specify the number of iterations (i.e. the
     * number of kernel buffers logged) when you start tracelogger.
     */
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_START));

    /*
     * The main() of this execution flow returns.
     * However, the main() function of the tracelogger
     * will return after registering the specified number
     * of events.
     */
    return (0);
}

Compile it, and then run tracelogger in one window:

tracelogger -d1 -n 3 -f all_classes.kev

and run the compiled program in another:

./all_classes

Despite how quickly the program ran, the amount of data it generated is rather overwhelming.

The trace data is in all_classes.kev; to examine it, type:

traceprinter -f all_classes.kev | less

The output from traceprinter will look something like this:

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
 -- 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:0x4f854048 CPU:00 THREAD  :THCREATE      pid:1511472 tid:1
t:0x4f854140 CPU:00 THREAD  :THRUNNING     pid:1511472 tid:1 
t:0x4f854910 CPU:00 KER_EXIT:TRACE_EVENT/01 ret_val:0x00000000 empty:0x00000000
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 
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 
t:0x4f879db8 CPU:00 KER_EXIT:MSG_REPLYV/15 ret_val:0 empty:0x00000000
t:0x4f87a84f CPU:00 KER_CALL:MSG_RECEIVEV/14 chid:0x00000001 rparts:1

...

This example demonstrates the capability of the trace module to capture huge amounts of data about the events. The first part of the trace data is the initial state information about all the running processes; to suppress it, start the tracing with _NTO_TRACE_STARTNOSTATE instead of _NTO_TRACE_START.

While it's good to know how to gather everything, we'll clearly need to be able to refine our search.

Gathering all events from one class

Now we'll gather all events from only one class, _NTO_TRACE_THREAD. This class is arbitrarily chosen to demonstrate filtering by classes; there's nothing particularly special about this class versus any other. For a full list of the possible classes, see “Classes and events” in the Events and the Kernel chapter in this guide.

Here's the source, one_class.c:

/*
 * $QNXLicenseC:
 * Copyright 2007, QNX Software Systems. All Rights Reserved.
 * 
 * You must obtain a written license from and pay applicable license fees to QNX 
 * Software Systems before you may reproduce, modify or distribute this software, 
 * or any work that includes all or part of this software.   Free development 
 * licenses are available for evaluation and non-commercial purposes.  For more 
 * information visit http://licensing.qnx.com or email licensing@qnx.com.
 *  
 * This file may contain contributions from others.  Please review this entire 
 * file for other proprietary rights or license notices, as well as the QNX 
 * Development Suite License Guide at http://licensing.qnx.com/license-guide/ 
 * for other information.
 * $
 */





#ifdef __USAGE
%C - instrumentation example

%C  - example that illustrates the very basic use of
      the TraceEvent() kernel call and the instrumentation
      module with tracelogger in a daemon mode.

      Only events from the thread class (_NTO_TRACE_THREAD)
      are monitored (intercepted).

      In order to use this example, start the tracelogger
      in the daemon mode as:

      tracelogger -n iter_number -d1

      with iter_number = your choice of 1 through 10

      After you start the example, the tracelogger (daemon)
      will log the specified number of iterations and then
      terminate. There are no messages printed upon successful
      completion of the example. You can view the intercepted
      events with the traceprinter utility.

      See accompanied documentation and comments within
      the sample source code for more explanations.
#endif

#include <sys/trace.h>

#include "instrex.h"

int main(int argc, char **argv)
{
    /*
     * Just in case, turn off all filters, since we
     * don't know their present state - go to the
     * known state of the filters.
     */
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_DELALLCLASSES));
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_CLRCLASSPID, _NTO_TRACE_KERCALL));
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_CLRCLASSTID, _NTO_TRACE_KERCALL));
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_CLRCLASSPID, _NTO_TRACE_THREAD));
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_CLRCLASSTID, _NTO_TRACE_THREAD));

    /*
     * Intercept only thread events
     */
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_ADDCLASS, _NTO_TRACE_THREAD));

    /*
     * Start tracing process
     *
     * During the tracing process, the tracelogger (which
     * is being executed in daemon mode) will log all events.
     * You can specify the number of iterations (i.e. the
     * number of kernel buffers logged) when you start tracelogger.
     */
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_START));

     /*
     * The main() of this execution flow returns.
     * However, the main() function of the tracelogger
     * will return after registering the specified number
     * of events.
     */
    return (0);
}

Compile it, and then run tracelogger in one window:

tracelogger -d1 -n 3 -f one_class.kev

and run the compiled program in another:

./one_class

The trace data is in one_class.kev; to examine it, type:

traceprinter -f one_class.kev | less

The output from traceprinter will look something like this:

TRACEPRINTER version 1.02
TRACEPARSER LIBRARY version 1.02
 -- HEADER FILE INFORMATION -- 
       TRACE_FILE_NAME:: one_class.kev
            TRACE_DATE:: Wed Jun 24 10:55:05 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 one_class.kev
 -- KERNEL EVENTS -- 
t:0x002c4d55 CPU:00 CONTROL: BUFFER sequence = 37, num_events = 714
t:0x002c4d55 CPU:00 THREAD  :THCREATE      pid:1 tid:1
t:0x002c5531 CPU:00 THREAD  :THREADY       pid:1 tid:1 priority:0 policy:1
t:0x002c5bbe CPU:00 THREAD  :THCREATE      pid:1 tid:2
t:0x002c5cd2 CPU:00 THREAD  :THRECEIVE     pid:1 tid:2 priority:255 policy:2
t:0x002c6185 CPU:00 THREAD  :THCREATE      pid:1 tid:3
t:0x002c6272 CPU:00 THREAD  :THRECEIVE     pid:1 tid:3 priority:255 policy:2
t:0x002c64eb CPU:00 THREAD  :THCREATE      pid:1 tid:4
t:0x002c65d8 CPU:00 THREAD  :THRECEIVE     pid:1 tid:4 priority:10 policy:2
t:0x002c67fc CPU:00 THREAD  :THCREATE      pid:1 tid:5
t:0x002c68ea CPU:00 THREAD  :THRECEIVE     pid:1 tid:5 priority:255 policy:2
t:0x002c6bae CPU:00 THREAD  :THCREATE      pid:1 tid:7
t:0x002c6c9b CPU:00 THREAD  :THRECEIVE     pid:1 tid:7 priority:10 policy:2
t:0x002c6f03 CPU:00 THREAD  :THCREATE      pid:1 tid:8
t:0x002c6ff0 CPU:00 THREAD  :THRECEIVE     pid:1 tid:8 priority:10 policy:2
t:0x002c72ec CPU:00 THREAD  :THCREATE      pid:1 tid:10
t:0x002c73d9 CPU:00 THREAD  :THRECEIVE     pid:1 tid:10 priority:10 policy:2
t:0x002c7665 CPU:00 THREAD  :THCREATE      pid:1 tid:11
t:0x002c7752 CPU:00 THREAD  :THRECEIVE     pid:1 tid:11 priority:10 policy:2
t:0x002c7a9d CPU:00 THREAD  :THCREATE      pid:1 tid:12
t:0x002c7b8a CPU:00 THREAD  :THRECEIVE     pid:1 tid:12 priority:10 policy:2
t:0x002c7e44 CPU:00 THREAD  :THCREATE      pid:1 tid:15
t:0x002c7f31 CPU:00 THREAD  :THRECEIVE     pid:1 tid:15 priority:10 policy:2
t:0x002c81a2 CPU:00 THREAD  :THCREATE      pid:1 tid:20
t:0x002c828f CPU:00 THREAD  :THRECEIVE     pid:1 tid:20 priority:10 policy:2
t:0x002c88e3 CPU:00 THREAD  :THCREATE      pid:2 tid:1
t:0x002c89d3 CPU:00 THREAD  :THREPLY       pid:2 tid:1 priority:10 policy:3
t:0x002c8fad CPU:00 THREAD  :THCREATE      pid:4099 tid:1
t:0x002c909a CPU:00 THREAD  :THRECEIVE     pid:4099 tid:1 priority:10 policy:3
t:0x002c95b7 CPU:00 THREAD  :THCREATE      pid:4100 tid:1
t:0x002c96a4 CPU:00 THREAD  :THRECEIVE     pid:4100 tid:1 priority:10 policy:3
t:0x002c9b6e CPU:00 THREAD  :THCREATE      pid:4101 tid:1
t:0x002c9ccd CPU:00 THREAD  :THSIGWAITINFO pid:4101 tid:1 priority:10 policy:3

...

Notice that we've significantly reduced the amount of output.

Gathering five events from four classes

Now that we can gather specific classes of events, we'll refine our search even further and gather only five specific types of events from four classes.

Here's the source, five_events.c:

/*
 * $QNXLicenseC:
 * Copyright 2007, QNX Software Systems. All Rights Reserved.
 * 
 * You must obtain a written license from and pay applicable license fees to QNX 
 * Software Systems before you may reproduce, modify or distribute this software, 
 * or any work that includes all or part of this software.   Free development 
 * licenses are available for evaluation and non-commercial purposes.  For more 
 * information visit http://licensing.qnx.com or email licensing@qnx.com.
 *  
 * This file may contain contributions from others.  Please review this entire 
 * file for other proprietary rights or license notices, as well as the QNX 
 * Development Suite License Guide at http://licensing.qnx.com/license-guide/ 
 * for other information.
 * $
 */





#ifdef __USAGE
%C - instrumentation example

%C  - example that illustrates the very basic use of
      the TraceEvent() kernel call and the instrumentation
      module with tracelogger in a daemon mode.

      Only five events from four classes are included and
      monitored. Class _NTO_TRACE_KERCALL is intercepted
      in a wide emitting mode.

      In order to use this example, start the tracelogger
      in the daemon mode as:

      tracelogger -n iter_number -d1

      with iter_number = your choice of 1 through 10

      After you start the example, the tracelogger (daemon)
      will log the specified number of iterations and then
      terminate. There are no messages printed upon successful
      completion of the example. You can view the intercepted
      events with the traceprinter utility.

      See accompanied documentation and comments within
      the example source code for more explanations.
#endif

#include <sys/trace.h>
#include <sys/kercalls.h>

#include "instrex.h"

int main(int argc, char **argv)
{
    /*
     * Just in case, turn off all filters, since we
     * don't know their present state - go to the
     * known state of the filters.
     */
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_DELALLCLASSES));
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_CLRCLASSPID, _NTO_TRACE_KERCALL));
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_CLRCLASSTID, _NTO_TRACE_KERCALL));
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_CLRCLASSPID, _NTO_TRACE_THREAD));
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_CLRCLASSTID, _NTO_TRACE_THREAD));

    /*
     * Set wide emitting mode
     */
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_SETALLCLASSESWIDE));

    /*
     * Intercept two events from class _NTO_TRACE_THREAD
     */
    TRACE_EVENT
    (
     argv[0],
     TraceEvent(_NTO_TRACE_ADDEVENT, _NTO_TRACE_THREAD, _NTO_TRACE_THRUNNING)
    );
    TRACE_EVENT
    (
     argv[0],
     TraceEvent(_NTO_TRACE_ADDEVENT, _NTO_TRACE_THREAD, _NTO_TRACE_THCREATE)
    );

    /*
     * Intercept one event from class _NTO_TRACE_PROCESS
     */
    TRACE_EVENT
    (
     argv[0],
     TraceEvent(_NTO_TRACE_ADDEVENT, _NTO_TRACE_PROCESS, _NTO_TRACE_PROCCREATE_NAME)
    );

    /*
     * Intercept one event from class _NTO_TRACE_INTENTER
     */
    TRACE_EVENT
    (
     argv[0],
     TraceEvent(_NTO_TRACE_ADDEVENT, _NTO_TRACE_INTENTER, _NTO_TRACE_INTFIRST)
    );

    /*
     * Intercept one event from class _NTO_TRACE_KERCALLEXIT,
     * event __KER_MSG_READV.
     */
    TRACE_EVENT
    (
     argv[0],
     TraceEvent(_NTO_TRACE_ADDEVENT, _NTO_TRACE_KERCALLEXIT, __KER_MSG_READV)
    );

    /*
     * Start tracing process
     *
     * During the tracing process, the tracelogger (which
     * is being executed in a daemon mode) will log all events.
     * You can specify the number of iterations (i.e. the
     * number of kernel buffers logged) when you start tracelogger.
     */
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_START));

    /*
     * The main() of this execution flow returns.
     * However, the main() function of the tracelogger
     * will return after registering the specified number
     * of events.
     */
    return (0);
}

Compile it, and then run tracelogger in one window:

tracelogger -d1 -n 3 -f five_events.kev

and run the compiled program in another:

./five_events

The trace data is in five_events.kev; to examine it, type:

traceprinter -f five_events.kev | less

The output from traceprinter will look something like this:

TRACEPRINTER version 1.02
TRACEPARSER LIBRARY version 1.02
 -- HEADER FILE INFORMATION -- 
       TRACE_FILE_NAME:: five_events.kev
            TRACE_DATE:: Wed Jun 24 10:56:04 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 five_events.kev
 -- KERNEL EVENTS -- 
t:0x1a14da34 CPU:00 CONTROL: BUFFER sequence = 41, num_events = 714
t:0x1a14da34 CPU:00 PROCESS :PROCCREATE_NAME
                      ppid:0
                       pid:1
                      name:proc/boot/procnto-smp-instr
t:0x1a14ea7d CPU:00 THREAD  :THCREATE      pid:1 tid:1
t:0x1a14ed04 CPU:00 THREAD  :THCREATE      pid:1 tid:2

...

t:0x1a1cc345 CPU:00 THREAD  :THRUNNING     pid:1 tid:15 priority:10 policy:2
t:0x1a1d01b9 CPU:00 THREAD  :THRUNNING     pid:8200 tid:5 priority:10 policy:3
t:0x1a1d6424 CPU:00 INT_ENTR:0x00000000 (0)       IP:0xb8229890
t:0x1a1ed261 CPU:00 THREAD  :THRUNNING     pid:1 tid:4 priority:10 policy:2
t:0x1a1f0016 CPU:00 THREAD  :THRUNNING     pid:426022 tid:1 priority:10 policy:2

...

t:0x2e77ebc5 CPU:00 THREAD  :THRUNNING     pid:1613871 tid:1 priority:10 policy:2
t:0x2e78598d CPU:00 THREAD  :THRUNNING     pid:8200 tid:5 priority:10 policy:3
t:0x2e7ac4fc CPU:00 INT_ENTR:0x00000000 (0)       IP:0xb8229f61
t:0x2e7cec3b CPU:00 KER_EXIT:MSG_READV/16
                    rbytes:22540
                      rmsg:"" (0x1a15080f 0x6e696273 0x6e69742f)
t:0x2e7da478 CPU:00 THREAD  :THRUNNING     pid:1003562 tid:1 priority:10 policy:2
t:0x2e7dc288 CPU:00 THREAD  :THRUNNING     pid:1 tid:15 priority:10 policy:2

...

We've now begun to selectively pick and choose events—the massive amount of data is now much more manageable.

Gathering kernel calls

The kernel calls are arguably the most important class of calls. This example shows not only filtering, but also the arguments intercepted by the instrumented kernel. In its base form, this program is similar to the one_class.c example that gathered only one class.

Here's the source, ker_calls.c:

/*
 * $QNXLicenseC:
 * Copyright 2007, QNX Software Systems. All Rights Reserved.
 * 
 * You must obtain a written license from and pay applicable license fees to QNX 
 * Software Systems before you may reproduce, modify or distribute this software, 
 * or any work that includes all or part of this software.   Free development 
 * licenses are available for evaluation and non-commercial purposes.  For more 
 * information visit http://licensing.qnx.com or email licensing@qnx.com.
 *  
 * This file may contain contributions from others.  Please review this entire 
 * file for other proprietary rights or license notices, as well as the QNX 
 * Development Suite License Guide at http://licensing.qnx.com/license-guide/ 
 * for other information.
 * $
 */





#ifdef __USAGE
%C - instrumentation example

%C  - [-n num]

%C  - example that illustrates the very basic use of
      the TraceEvent() kernel call and the instrumentation
      module with tracelogger in a daemon mode.

      All thread states and all/one (specified) kernel
      call number are intercepted. The kernel call(s)
      is(are) intercepted in wide emitting mode.

Options:
    -n <num> kernel call number to be intercepted
       (default is all)

      In order to use this example, start the tracelogger
      in the daemon mode as:

      tracelogger -n iter_number -d1

      with iter_number = your choice of 1 through 10

      After you start the example, the tracelogger (daemon)
      will log the specified number of iterations and then
      terminate. There are no messages printed upon successful
      completion of the example. You can view the intercepted
      events with the traceprinter utility.

      See accompanied documentation and comments within
      the sample source code for more explanations.
#endif

#include <sys/trace.h>
#include <unistd.h>
#include <stdlib.h>

#include "instrex.h"

int main(int argc, char **argv)
{
    int arg_var;       /* input arguments parsing support      */
    int call_num=(-1); /* kernel call number to be intercepted */

    /* Parse command line arguments
     *
     * - get optional kernel call number
     */
    while((arg_var=getopt(argc, argv,"n:"))!=(-1)) {
        switch(arg_var) 
        {
            case 'n': /* get kernel call number */
                call_num = strtoul(optarg, NULL, 10);
                break;
            default:  /* unknown */
                TRACE_ERROR_MSG
                (
                 argv[0],
                 "error parsing command-line arguments - exiting\n"
                );

                return (-1);
        }
    }           

    /*
     * Just in case, turn off all filters, since we
     * don't know their present state - go to the
     * known state of the filters.
     */
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_DELALLCLASSES));
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_CLRCLASSPID, _NTO_TRACE_KERCALL));
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_CLRCLASSTID, _NTO_TRACE_KERCALL));
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_CLRCLASSPID, _NTO_TRACE_THREAD));
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_CLRCLASSTID, _NTO_TRACE_THREAD));

    /*
     * Set wide emitting mode for all classes and
     * their events. 
     */
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_SETALLCLASSESWIDE));

    /*
     * Intercept _NTO_TRACE_THREAD class
     * We need it to know the state of the active thread.
     */
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_ADDCLASS, _NTO_TRACE_THREAD));

    /*
     * Add all/one kernel call
     */
    if(call_num != (-1)) {
        TRACE_EVENT
        (
         argv[0],
         TraceEvent(_NTO_TRACE_ADDEVENT, _NTO_TRACE_KERCALL, call_num)
        );
    } else {
        TRACE_EVENT
        (
         argv[0],
         TraceEvent(_NTO_TRACE_ADDCLASS, _NTO_TRACE_KERCALL)
        );
    }

    /*
     * Start tracing process
     *
     * During the tracing process, the tracelogger (which
     * is being executed in a daemon mode) will log all events.
     * You can specify the number of iterations (i.e. the
     * number of kernel buffers logged) when you start tracelogger.
     */
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_START));

    /*
     * The main() of this execution flow returns.
     * However, the main() function of the tracelogger
     * will return after registering the specified number
     * of events.
     */
    return (0);
}

Compile it, and then run tracelogger in one window:

tracelogger -d1 -n 3 -f ker_calls.all.kev

and run the compiled program in another:

./ker_calls

The trace data is in ker_calls.all.kev; to examine it, type:

traceprinter -f ker_calls.all.kev | less

The output from traceprinter will look something like this:

TRACEPRINTER version 1.02
TRACEPARSER LIBRARY version 1.02
 -- HEADER FILE INFORMATION -- 
       TRACE_FILE_NAME:: ker_calls.all.kev
            TRACE_DATE:: Wed Jun 24 10:57:01 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 ker_calls.all.kev
 -- KERNEL EVENTS -- 
t:0x463ad541 CPU:00 CONTROL: BUFFER sequence = 45, num_events = 714
t:0x463ad541 CPU:00 THREAD  :THCREATE      pid:1 tid:1
t:0x463adbe1 CPU:00 THREAD  :THREADY       pid:1 tid:1 priority:0 policy:1
t:0x463adfa8 CPU:00 THREAD  :THCREATE      pid:1 tid:2
t:0x463ae098 CPU:00 THREAD  :THRECEIVE     pid:1 tid:2 priority:255 policy:2
t:0x463ae375 CPU:00 THREAD  :THCREATE      pid:1 tid:3

...

t:0x463d59b6 CPU:00 THREAD  :THSIGWAITINFO pid:1658927 tid:2 priority:10 policy:2
t:0x463d5cb2 CPU:00 THREAD  :THCREATE      pid:1663024 tid:1
t:0x463d5da7 CPU:00 THREAD  :THRUNNING     pid:1663024 tid:1 priority:10 policy:2
t:0x463d666e CPU:00 KER_EXIT:TRACE_EVENT/01 ret_val:0x00000000 empty:0x00000000
t:0x463d8e65 CPU:00 KER_CALL:THREAD_DESTROY/47
                       tid:-1
                  priority:-1
                  status_p:0
t:0x463da615 CPU:00 KER_EXIT:THREAD_DESTROY/47 ret_val:0x00000030 empty:0x00000000
t:0x463daf0a CPU:00 KER_CALL:THREAD_DESTROYALL/48 empty:0x00000000 empty:0x00000000
t:0x463db531 CPU:00 THREAD  :THDESTROY     pid:1663024 tid:1
t:0x463dc114 CPU:00 THREAD  :THDEAD        pid:1663024 tid:1 priority:10 policy:2
t:0x463dc546 CPU:00 THREAD  :THRUNNING     pid:1 tid:1 priority:0 policy:1
t:0x463df45d CPU:00 THREAD  :THRUNNING     pid:1 tid:4 priority:10 policy:2
t:0x463dfa7f CPU:00 THREAD  :THREADY       pid:1 tid:1 priority:0 policy:1
t:0x463e36b4 CPU:00 KER_CALL:THREAD_CREATE/46
                       pid:1663024
                    func_p:f0023170
                     arg_p:eff4e000
                     flags:0x00000000
                 stacksize:10116
               stackaddr_p:eff4e264
                exitfunc_p:0
                    policy:0
            sched_priority:0
         sched_curpriority:0
   param.__ss_low_priority:0
       param.__ss_max_repl:0
param.__ss_repl_period.tv_sec:0
param.__ss_repl_period.tv_nsec:0
param.__ss_init_budget.tv_sec:0
param.__ss_init_budget.tv_nsec:0
               param.empty:0
               param.empty:0
                 guardsize:0
                     empty:0
                     empty:0
                     empty:0
t:0x463e50b0 CPU:00 THREAD  :THCREATE      pid:1663024 tid:1
t:0x463e51d0 CPU:00 THREAD  :THWAITTHREAD  pid:1 tid:4 priority:10 policy:2
t:0x463e5488 CPU:00 THREAD  :THRUNNING     pid:1663024 tid:1 priority:10 policy:2
t:0x463e6408 CPU:00 THREAD  :THREADY       pid:1 tid:4 priority:10 policy:2

...

The ker_calls.c program takes a -n option that lets us view only one type of kernel call. Let's run this program again, specifying the number 14, which signifies __KER_MSG_RECEIVE. For a full list of the values associated with the -n option, see /usr/include/sys/kercalls.h.

Run tracelogger in one window:

tracelogger -d1 -n 3 -f ker_calls.14.kev

and run the program in another:

./ker_calls -n 14

The trace data is in ker_calls.14.kev; to examine it, type:

traceprinter -f ker_calls.14.kev | less

The output from traceprinter will look something like this:

TRACEPRINTER version 1.02
TRACEPARSER LIBRARY version 1.02
 -- HEADER FILE INFORMATION -- 
       TRACE_FILE_NAME:: ker_calls.14.kev
            TRACE_DATE:: Wed Jun 24 13:39:20 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 ker_calls.14.kev
 -- KERNEL EVENTS -- 
t:0x73bf28d0 CPU:00 CONTROL: BUFFER sequence = 62, num_events = 714
t:0x73bf28d0 CPU:00 THREAD  :THCREATE      pid:1 tid:1
t:0x73bf2e16 CPU:00 THREAD  :THREADY       pid:1 tid:1 priority:0 policy:1
t:0x73bf3203 CPU:00 THREAD  :THCREATE      pid:1 tid:2

...

t:0x73c21746 CPU:00 THREAD  :THRUNNING     pid:1 tid:1 priority:0 policy:1
t:0x73c24352 CPU:00 THREAD  :THRUNNING     pid:1 tid:15 priority:10 policy:2
t:0x73c247e0 CPU:00 THREAD  :THREADY       pid:1 tid:1 priority:0 policy:1
t:0x73c2547b CPU:00 KER_EXIT:MSG_RECEIVEV/14
                     rcvid:0x00000000
                      rmsg:"" (0x00000000 0x00000081 0x001dd030)
                  info->nd:0
               info->srcnd:0
                 info->pid:1953840
                 info->tid:1
                info->chid:1
               info->scoid:1073741874
                info->coid:1073741824
              info->msglen:0
           info->srcmsglen:56
           info->dstmsglen:24
            info->priority:10
               info->flags:0
            info->reserved:0
t:0x73c29270 CPU:00 THREAD  :THCREATE      pid:1953840 tid:1
t:0x73c293ca CPU:00 THREAD  :THWAITTHREAD  pid:1 tid:15 priority:10 policy:2
t:0x73c2964a CPU:00 THREAD  :THRUNNING     pid:1953840 tid:1 priority:10 policy:2
t:0x73c2a36c CPU:00 THREAD  :THREADY       pid:1 tid:15 priority:10 policy:2
t:0x73c2fccc CPU:00 THREAD  :THREPLY       pid:1953840 tid:1 priority:10 policy:2
t:0x73c30f6b CPU:00 THREAD  :THREADY       pid:159762 tid:1 priority:10 policy:3
t:0x73c311b0 CPU:00 THREAD  :THRUNNING     pid:159762 tid:1 priority:10 policy:3
t:0x73c31835 CPU:00 KER_EXIT:MSG_RECEIVEV/14
                     rcvid:0x0000004f
                      rmsg:"" (0x00040116 0x00000000 0x00000004)
                  info->nd:0
               info->srcnd:0
                 info->pid:1953840
                 info->tid:1
                info->chid:1
               info->scoid:1073741903
                info->coid:0
              info->msglen:4
           info->srcmsglen:4
           info->dstmsglen:0
            info->priority:10
               info->flags:0
            info->reserved:0
t:0x73c3a359 CPU:00 THREAD  :THREADY       pid:1953840 tid:1 priority:10 policy:2
t:0x73c3af50 CPU:00 KER_CALL:MSG_RECEIVEV/14 chid:0x00000001 rparts:1
t:0x73c3b25e CPU:00 THREAD  :THRECEIVE     pid:159762 tid:1 priority:10 policy:3

...

Event handling - simple

In this example, we intercept two events from two different classes. Each event has an event handler attached to it; the event handlers are closing and opening the stream. Here's the source, eh_simple.c:

/*
 * $QNXLicenseC:
 * Copyright 2007, QNX Software Systems. All Rights Reserved.
 * 
 * You must obtain a written license from and pay applicable license fees to QNX 
 * Software Systems before you may reproduce, modify or distribute this software, 
 * or any work that includes all or part of this software.   Free development 
 * licenses are available for evaluation and non-commercial purposes.  For more 
 * information visit http://licensing.qnx.com or email licensing@qnx.com.
 *  
 * This file may contain contributions from others.  Please review this entire 
 * file for other proprietary rights or license notices, as well as the QNX 
 * Development Suite License Guide at http://licensing.qnx.com/license-guide/ 
 * for other information.
 * $
 */





#ifdef __USAGE
%C - instrumentation example

%C  - example that illustrates the very basic use of
      the TraceEvent() kernel call and the instrumentation
      module with tracelogger in a daemon mode.

      Two events from two classes are included and monitored
      interchangeably. The flow control of monitoring the
      specified events is controlled with attached event
      handlers.

      In order to use this example, start the tracelogger
      in the daemon mode as:

      tracelogger -n 1 -d1

      After you start the example, the tracelogger (daemon)
      will log the specified number of iterations and then
      terminate. There are no messages printed upon successful
      completion of the example. You can view the intercepted
      events with the traceprinter utility.

      See accompanied documentation and comments within
      the sample source code for more explanations.
#endif

#include <unistd.h>
#include <sys/trace.h>
#include <sys/kercalls.h>

#include "instrex.h"

/*
 * Prepare event structure where the event data will be
 * stored and passed to an event handler.
 */
event_data_t e_d_1;
_Uint32t     data_array_1[20]; /* 20 elements for potential args. */

event_data_t e_d_2;
_Uint32t     data_array_2[20]; /* 20 elements for potential args. */

/*
 * Global state variable that controls the
 * event flow between two events
 */
int g_state;

/*
 * Event handler attached to the event __KER_MSG_SENDV
 * from the _NTO_TRACE_KERCALL class.
 */
int call_msg_send_eh(event_data_t* e_d)
{
    if(g_state) {
        g_state = !g_state;
        return (1);
    }

    return (0);
}

/*
 * Event handler attached to the event _NTO_TRACE_THRUNNING
 * from the _NTO_TRACE_THREAD (thread) class.
 */
int thread_run_eh(event_data_t* e_d)
{
    if(!g_state) {
        g_state = !g_state;
        return (1);
    }

    return (0);
}


int main(int argc, char **argv)
{
    /*
     * First fill arrays inside event data structures
     */
    e_d_1.data_array = data_array_1;
    e_d_2.data_array = data_array_2;

    /*
     * Just in case, turn off all filters, since we
     * don't know their present state - go to the
     * known state of the filters.
     */
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_DELALLCLASSES));
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_CLRCLASSPID, _NTO_TRACE_KERCALL));
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_CLRCLASSTID, _NTO_TRACE_KERCALL));
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_CLRCLASSPID, _NTO_TRACE_THREAD));
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_CLRCLASSTID, _NTO_TRACE_THREAD));

    /*
     * Set fast emitting mode
     */
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_SETALLCLASSESFAST));

    /*
     * Obtain I/O privileges before adding event handlers
     */
    if (ThreadCtl(_NTO_TCTL_IO, 0)!=EOK) { /* obtain I/O privileges         */
        (void) fprintf(stderr, "argv[0]: Failed to obtain I/O privileges\n");

        return (-1);
    }

    /*
     * Intercept one event from class _NTO_TRACE_KERCALL,
     * event __KER_MSG_SENDV.
     */
    TRACE_EVENT
    (
     argv[0],
     TraceEvent(_NTO_TRACE_ADDEVENT, _NTO_TRACE_KERCALLENTER, __KER_MSG_SENDV)
    );

    /*
     * Add event handler to the event __KER_MSG_SENDV
     * from _NTO_TRACE_KERCALL class.
     */
    TRACE_EVENT
    (
     argv[0],
     TraceEvent(_NTO_TRACE_ADDEVENTHANDLER, _NTO_TRACE_KERCALLENTER,
                __KER_MSG_SENDV, call_msg_send_eh, &e_d_1)
    );

    /*
     * Intercept one event from class _NTO_TRACE_THREAD
     */
    TRACE_EVENT
    (
     argv[0],
     TraceEvent(_NTO_TRACE_ADDEVENT, _NTO_TRACE_THREAD, _NTO_TRACE_THRUNNING)
    );


    /*
     * Add event event handler to the _NTO_TRACE_THRUNNING event
     * from the _NTO_TRACE_THREAD (thread) class.
     */
    TRACE_EVENT
    (
     argv[0],
     TraceEvent(_NTO_TRACE_ADDEVENTHANDLER, _NTO_TRACE_THREAD,
                _NTO_TRACE_THRUNNING, thread_run_eh, &e_d_2)
    );

    /*
     * Start tracing process
     *
     * During the tracing process, the tracelogger (which
     * is being executed in a daemon mode) will log all events.
     * The number of iterations has been specified as 1.
     */
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_START));

    /*
     * During one second collect all events
     */
    (void) sleep(1);

    /*
     * Stop tracing process by closing the event stream.
     */
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_STOP));

    /*
     * Flush the internal buffer since the number
     * of stored events could be less than
     * "high water mark" of one buffer (715 events).
     *
     * The tracelogger will probably terminate at
     * this point, since it has been executed with
     * one iteration (-n 1 option).
     */
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_FLUSHBUFFER));

    /*
     * Delete event handlers before exiting to avoid execution
     * in the missing address space.
     */
    TRACE_EVENT
    (
     argv[0],
     TraceEvent(_NTO_TRACE_DELEVENTHANDLER, _NTO_TRACE_KERCALLENTER, __KER_MSG_SENDV)
    );
    TRACE_EVENT
    (
     argv[0],
     TraceEvent(_NTO_TRACE_DELEVENTHANDLER, _NTO_TRACE_THREAD, _NTO_TRACE_THRUNNING)
    );

    /*
     * Wait one second before terminating to hold the address space
     * of the event handlers.
     */
    (void) sleep(1);

    return (0);
}

Compile it, and then run tracelogger in one window:

tracelogger -d1 -n 1 -f eh_simple.kev

For this example, we've specified the number of iterations to be 1.

Run the compiled program in another window:

./eh_simple

The trace data is in eh_simple.kev; to examine it, type:

traceprinter -f eh_simple.kev | less

The output from traceprinter will look something like this:

TRACEPRINTER version 1.02
TRACEPARSER LIBRARY version 1.02
 -- HEADER FILE INFORMATION -- 
       TRACE_FILE_NAME:: eh_simple.kev
            TRACE_DATE:: Wed Jun 24 10:58:41 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 1 -f eh_simple.kev
 -- KERNEL EVENTS -- 
t:0x33139a74 CPU:00 CONTROL: BUFFER sequence = 53, num_events = 482
t:0x33139a74 CPU:00 THREAD  :THRUNNING     pid:1749040 tid:1 
t:0x362d0710 CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000003 msg:"" (0x00100102)
t:0x362d1d04 CPU:00 THREAD  :THRUNNING     pid:217117 tid:1 
t:0x362e8e3e CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000000 msg:"" (0x00200113)
t:0x362ea264 CPU:00 THREAD  :THRUNNING     pid:4102 tid:8 
t:0x362f1248 CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000003 msg:"" (0x00000106)
t:0x362f1c67 CPU:00 THREAD  :THRUNNING     pid:217117 tid:1 
t:0x362fd08b CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000003 msg:"" (0x00100102)
t:0x362fd949 CPU:00 THREAD  :THRUNNING     pid:217117 tid:1 
t:0x36305424 CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000003 msg:"" (0x00000106)
t:0x36305e35 CPU:00 THREAD  :THRUNNING     pid:217117 tid:1 
t:0x3630a572 CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000003 msg:"" (0x00000106)
t:0x3630aeb7 CPU:00 THREAD  :THRUNNING     pid:217117 tid:1 
t:0x3631bd5b CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000003 msg:"" (0x00100102)
t:0x3631c6aa CPU:00 THREAD  :THRUNNING     pid:217117 tid:1 
t:0x363253bb CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000003 msg:"" (0x00000106)
t:0x36325d95 CPU:00 THREAD  :THRUNNING     pid:217117 tid:1 
t:0x369b2349 CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000003 msg:"" (0x00000106)
t:0x369b2bbe CPU:00 THREAD  :THRUNNING     pid:217117 tid:1 
t:0x369b88d8 CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000007 msg:"" (0x00100106)
t:0x369b974a CPU:00 THREAD  :THRUNNING     pid:1 tid:15 
t:0x369c48ab CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000008 msg:"" (0x00100106)
t:0x369c53db CPU:00 THREAD  :THRUNNING     pid:126997 tid:2 
t:0x369cee17 CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000008 msg:"" (0x00100106)
t:0x369cf533 CPU:00 THREAD  :THRUNNING     pid:126997 tid:2 
t:0x369d82b6 CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000009 msg:"" (0x00100106)
t:0x369d9178 CPU:00 THREAD  :THRUNNING     pid:8200 tid:10 
t:0x369eae84 CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000006 msg:"" (0x00020100)
t:0x369eb687 CPU:00 THREAD  :THRUNNING     pid:1 tid:15 
t:0x369f56b1 CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000006 msg:"" (0x00020100)

...

This is an important example because it demonstrates the use of the dynamic rules filter to perform tasks beyond basic filtering.

Inserting a user simple event

This example demonstrates the insertion of a user event into the event stream. Here's the source, usr_event_simple.c:

/*
 * $QNXLicenseC:
 * Copyright 2007, QNX Software Systems. All Rights Reserved.
 * 
 * You must obtain a written license from and pay applicable license fees to QNX 
 * Software Systems before you may reproduce, modify or distribute this software, 
 * or any work that includes all or part of this software.   Free development 
 * licenses are available for evaluation and non-commercial purposes.  For more 
 * information visit http://licensing.qnx.com or email licensing@qnx.com.
 *  
 * This file may contain contributions from others.  Please review this entire 
 * file for other proprietary rights or license notices, as well as the QNX 
 * Development Suite License Guide at http://licensing.qnx.com/license-guide/ 
 * for other information.
 * $
 */





#ifdef __USAGE
%C - instrumentation example

%C  - example that illustrates the very basic use of
      the TraceEvent() kernel call and the instrumentation
      module with tracelogger in a daemon mode.

      All classes and their events are included and monitored.
      Additionally, four user-generated simple events and
      one string event are intercepted.

      In order to use this example, start the tracelogger
      in the daemon mode as:

      tracelogger -n iter_number -d1

      with iter_number = your choice of 1 through 10

      After you start the example, the tracelogger (daemon)
      will log the specified number of iterations and then
      terminate. There are no messages printed upon successful
      completion of the example. You can view the intercepted
      events with the traceprinter utility. The intercepted
      user events (class USREVENT) have event IDs
      (EVENT) equal to: 111, 222, 333, 444 and 555.

      See accompanied documentation and comments within
      the sample source code for more explanations.
#endif

#include <sys/trace.h>
#include <unistd.h>

#include "instrex.h"

int main(int argc, char **argv)
{
    /*
     * Just in case, turn off all filters, since we
     * don't know their present state - go to the
     * known state of the filters.
     */
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_DELALLCLASSES));
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_CLRCLASSPID, _NTO_TRACE_KERCALL));
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_CLRCLASSTID, _NTO_TRACE_KERCALL));
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_CLRCLASSPID, _NTO_TRACE_THREAD));
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_CLRCLASSTID, _NTO_TRACE_THREAD));

    /*
     * Set fast emitting mode for all classes and
     * their events. 
     */
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_SETALLCLASSESFAST));

    /*
     * Intercept all event classes
     */
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_ADDALLCLASSES));

    /*
     * Start tracing process
     *
     * During the tracing process, the tracelogger (which
     * is being executed in a daemon mode) will log all events.
     * You can specify the number of iterations (i.e. the
     * number of kernel buffers logged) when you start tracelogger.
     */
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_START));

    /*
     * Insert four user-defined simple events and one string
     * event into the event stream. The user events have
     * arbitrary event IDs: 111, 222, 333, 444, and 555
     * (possible values are in the range 0...1023).
     * The user events with ID=(111, ..., 444) are simple events
     * that have two numbers attached: ({1,11}, ..., {4,44}).
     * The user string event (ID 555) includes the string,
     * "Hello world".
     */
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_INSERTSUSEREVENT, 111, 1, 11));
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_INSERTSUSEREVENT, 222, 2, 22));
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_INSERTSUSEREVENT, 333, 3, 33));
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_INSERTSUSEREVENT, 444, 4, 44));
    TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_INSERTUSRSTREVENT,555, "Hello world" ));

    /*
     * The main() of this execution flow returns.
     * However, the main() function of the tracelogger
     * will return after registering the specified number
     * of events.
     */
    return (0);
}

Compile it, and then run tracelogger in one window:

tracelogger -d1 -n 3 -f usr_event_simple.kev

and run the compiled program in another:

./usr_event_simple

The trace data is in usr_event_simple.kev; to examine it, type:

traceprinter -f usr_event_simple.kev | less

The output from traceprinter will look something like this:

TRACEPRINTER version 1.02
TRACEPARSER LIBRARY version 1.02
 -- HEADER FILE INFORMATION -- 
       TRACE_FILE_NAME:: usr_event_simple.kev
            TRACE_DATE:: Wed Jun 24 10:59:34 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 usr_event_simple.kev
 -- KERNEL EVENTS -- 
t:0x254620e4 CPU:00 CONTROL: BUFFER sequence = 54, num_events = 714

...

t:0x25496c81 CPU:00 PROCESS :PROCCREATE_NAME
                      ppid:426022
                       pid:1810480
                      name:./usr_event_simple
t:0x2549701a CPU:00 THREAD  :THCREATE      pid:1810480 tid:1
t:0x25497112 CPU:00 THREAD  :THRUNNING     pid:1810480 tid:1 
t:0x2549793a CPU:00 KER_EXIT:TRACE_EVENT/01 ret_val:0x00000000 empty:0x00000000
t:0x25497f48 CPU:00 USREVENT:EVENT:111, d0:0x00000001 d1:0x0000000b
t:0x254982c5 CPU:00 USREVENT:EVENT:222, d0:0x00000002 d1:0x00000016
t:0x25498638 CPU:00 USREVENT:EVENT:333, d0:0x00000003 d1:0x00000021
t:0x25498996 CPU:00 USREVENT:EVENT:444, d0:0x00000004 d1:0x0000002c
t:0x25499451 CPU:00 USREVENT:EVENT:555 STR:"Hello world"
t:0x2549bde5 CPU:00 KER_CALL:THREAD_DESTROY/47 tid:-1 status_p:0
t:0x2549d0d6 CPU:00 KER_EXIT:THREAD_DESTROY/47 ret_val:0x00000030 empty:0x00000000
t:0x2549d8ae CPU:00 KER_CALL:THREAD_DESTROYALL/48 empty:0x00000000 empty:0x00000000

...

Inserting your own events lets you flag events or bracket groups of events to isolate them for study. It's also useful for inserting internal, customized information into the event stream.