Caution: This version of this document is no longer maintained. For the latest documentation, see http://www.qnx.com/developers/docs.

Tutorial

Starting out

Setting up the Instrumented Kernel

The Instrumented Kernel is a drop-in replacement for the noninstrumented kernel. In fact, when you're not tracing any events, the Instrumented Kernel operates at almost the same speed as the normal kernel. To use the Instrumented Kernel rather than the normal kernel:

  1. In your buildfile, replace the entry for procnto with procnto-instr.
  2. Run the mkifs utility to rebuild the image.
  3. Replace your current boot image with the new one.
  4. Add tracelogger and traceprinter to your buildfile or target.

Note that the Instrumented Kernel is slightly larger than the normal kernel.

For more information about mkifs, see the Utilities Reference.

Tutorial overview

As you go through this tutorial, we'll ask you to save files.

The "tracebuffer" files are binary files that can be interpreted only with the libtraceparser library, which the traceprinter utility uses. To help you ensure you're getting the right results, we've used the same names in our documentation. For example, when we ask you to save to the file tb.bare, we'll show the traceprinter output here as tb.bare.txt, which is a file you can view with your favorite text editor.

Because the default number of buffers is 32, which produces a rather large file, 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.

The tracelogger in normal mode

Interrupts, iterations, and events

With no other processes running, type:

tracelogger -f tb.bare

You'll see that the interrupts increment concurrently with the iterations. This is a good indication that the system was partially idle during the logging process.

The interrupts are not the traditional interrupts -- they're "fake" ones during which the tracelogger saves the buffer just before flushing it.

You should also note that every entry for events tends to be 715, or very nearly 715. This is a count of how many events were logged in each buffer before tracelogger issued an interrupt to start writing to a new buffer. The default buffer holds 1024 events, numbered from 0 to 1023. At the high-water mark, when the buffer is 70% full, the system writes the buffer to file and flushes the buffer from memory.

Slow systems and busy systems

The Instrumented Kernel kernel has been designed to be quite rugged and to have only a small performance penalty. Because the tracelogger, in its normal mode, saves large chunks of data, the amount of data it has to handle may overwhelm slow systems or systems with limited resources.

Since we all have different systems and there's no easy way to slow them down consistently, we'll cheat and set the buffer to 1. The default number of buffers is 32, which is plenty to keep the system running along without problems. When the buffer is only 1, the system tries to save the buffer at the high-water mark while at the same time rewriting it from the beginning. Because it's impossible to save the entire buffer before any more kernel calls occur, what's saved is garbage data or, at best, partial data.

Enter:

tracelogger -b 1

The results show the number of events as being nowhere near 715. Even though it won't happen in this example, if the number of events is 0, you likely have a problem.

As a general rule, the number of events should be consistently the high-water mark of the maximum number of events.

The iterations are the number of times the system has written to the buffer and the interrupts are an indication of how often the system saved (or tried to save) the buffer. If the number of interrupts is less than the number of iterations, it's a good indication that some data has been lost. This is particularly true if the number of events is ever shown to be 0. It's not serious if interrupts trail iterations by only 1.

The tracelogger in daemon mode

Overview

Normal mode vs. Daemon mode

In normal mode, tracelogger by default gathers all events in fast mode.

In daemon mode, tracelogger gathers no events--you must specify the events you wish to gather.

When you run tracelogger from the command line, the default is in normal mode. Normal mode allows for fast setup but the amount of information it generates is overwhelming.

Daemon mode can provide only the information you want, but at the expense of setup time and complexity. To start daemon mode, use the tracelogger -d1 option. In daemon mode, tracelogger waits for a signal to start. We'll provide the start signal with a program.


Note: If you also specify the -E option, tracelogger runs in daemon mode, but lets you configure the trace from the command line. Your application still needs to start the tracing from its code.

Understanding the tutorial format

To reduce repetition and keep the programs simple, some functionality has been put into a header file. You'll have to save the included instrex.h file in order for the programs to compile.

Each of these sample programs uses a similar format:

  1. Compile the C file into a file of the same name, without the .c extension
  2. Run the Command.
  3. In a separate terminal window, run the compiled C file. Some examples use options. Watch the first terminal window. In a few seconds the tracelogger will finish running.
  4. If you run the program, it generates its own Sample result file; if you didn't run the program, take a look at our traceprinter output. (Note that different versions and systems will create slightly different results.)

Note: You may include these samples in your code as long as you comply with the copyright.

Gathering all events from all classes

C File
all_classes.c
Command
tracelogger -d1 -n 3 -f all_classes.results
Running C File
all_classes
Sample result file
all_classes.results.txt
Viewing
traceprinter -f all_classes.results

In our first example, we'll set up daemon mode to gather all events from all classes. Despite how quickly the program ran, the amount of data it generated is rather overwhelming. Feel free to interrupt the traceprinter-- it'll list data for a while.

This example demonstrates the capability of the trace module to capture huge amounts of data about the events.

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

C File
one_class.c
Command
tracelogger -d1 -n 3 -f one_class.results
Running C File
one_class
Sample result file
one_class.results.txt
Viewing
traceprinter -f one_class.results

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 TraceEvent() in the Neutrino Library Reference.

Notice that the results are a little more refined as well as consistent.

Gathering five events from four classes

C File
five_events.c
Command
tracelogger -d1 -n 3 -f five_events.results
Running C File
five_events
Sample result file
five_events.results.txt
Viewing
traceprinter -f five_events.results

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. We've now begun to selectively pick and choose events--the massive amount of data is now much more manageable.

Gathering kernel calls

C File
ker_calls.c
Command
tracelogger -d1 -n 3 -f ker_calls.all.results
Running C File
ker_calls
Sample result file
ker_calls.all.results.txt
Viewing
traceprinter -f ker_calls.all.results

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.

C File
ker_calls.c
Command
tracelogger -d1 -n 3 -f ker_calls.14.results
Running C File
ker_calls -n 14
Sample result file
ker_calls.14.results.txt
Viewing
traceprinter -f ker_calls.14.results

Our C File has an extra feature in it that lets us view only one type of kernel call--the number 14 signifies __KER_MSG_RECEIVE. For a full list of the values associated with the -n option, see /usr/include/sys/kercalls.h.

Event handling - simple

C File
eh_simple.c
Command
tracelogger -d1 -n 3 -f eh_simple.results
Running C File
eh_simple
Sample result file
eh_simple.results.txt
Viewing
traceprinter -f eh_simple.results

Now, two events from two different classes are intercepted. Each event has an event handler attached to it; the event handlers are closing and opening the stream.

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

User event - simple

C File
usr_event_simple.c
Command
tracelogger -d1 -n 3 -f usr_event_simple.results
Running C File
usr_event_simple
Sample result file
usr_event_simple.results.txt
Viewing
traceprinter -f usr_event_simple.results

This example demonstrates the insertion of a user event into the event stream.

Being able to insert "artificial" events allows you to "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.

Header file: instrex.h

/*
 * Copyright 2003, QNX Software Systems. All Rights Reserved.
 *
 * This source code may contain confidential information of QNX Software
 * Systems (QSS) and its licensors. Any use, reproduction,
 * modification, disclosure, distribution or transfer of this software,
 * or any software which includes or is based upon any of this code, is
 * prohibited unless expressly authorized by QSS by written agreement. For
 * more information (including whether this source code file has been
 * published) please email licensing@qnx.com.
 */

/*
 *  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 states 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

C File: all_classes.c

/*
 * Copyright 2003, QNX Software Systems. All Rights Reserved.
 *
 * This source code may contain confidential information of QNX Software
 * Systems (QSS) and its licensors. Any use, reproduction,
 * modification, disclosure, distribution or transfer of this software,
 * or any software which includes or is based upon any of this code, is
 * prohibited unless expressly authorized by QSS by written agreement. For
 * more information (including whether this source code file has been
 * published) please email licensing@qnx.com.
 */

#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 deamon mode as:

	  tracelogger -n iter_number -d1

	  with iter_number = your choice of 1 through 10

	  After executing the example, the tracelogger (daemon)
	  will log the specified number of iterations and then
	  terminate. There are no messages printed uppon 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 "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.
	 * The number of full logged iterations is user specified.
	 */
	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);
}

Sample result file: all_classes.results.txt

TRACEPRINTER version 0.97
TRACEPARSER LIBRARY version 0.98
 -- HEADER FILE INFORMATION -- 
       TRACE_FILE_NAME:: /dev/shmem/tracebuffer
            TRACE_DATE:: Fri Aug 17 09:08:06 2001
       TRACE_VER_MAJOR:: 0
       TRACE_VER_MINOR:: 97
   TRACE_LITTLE_ENDIAN:: TRUE
        TRACE_ENCODING:: 16 byte events
       TRACE_BOOT_DATE:: Fri Aug 17 09:02:16 2001
  TRACE_CYCLES_PER_SEC:: 132980400
         TRACE_CPU_NUM:: 1
         TRACE_SYSNAME:: QNX
        TRACE_NODENAME:: localhost
     TRACE_SYS_RELEASE:: 6.1.0
     TRACE_SYS_VERSION:: 2001/08/15-08:15:15
         TRACE_MACHINE:: x86pc
     TRACE_SYSPAGE_LEN:: 2248
 -- KERNEL EVENTS -- 
t:0xbcb12bdf CPU:00 CONTROL :TIME msb:0x0000000b, lsb(offset):0xbcb128b3
t:0xbcb135fb CPU:00 PROCESS :PROCCREATE_NAME
                      ppid:0
                       pid:1
                      name:/home/mmacies/instrumentation/x86/procnto-instr
															.
															.
															.
t:0xbcb1db36 CPU:00 THREAD  :THRUNNING     pid:98319 tid:1
t:0xbcb1e090 CPU:00 KER_EXIT:TRACE_EVENT/01 ret_val:0x00000000 empty:0x00000000
t:0xbcb1f03c CPU:00 KER_CALL:THREAD_DESTROY/47 tid:-1 status_p:0
t:0xbcb1f870 CPU:00 KER_EXIT:THREAD_DESTROY/47 ret_val:0x00000030 empty:0x00000000
t:0xbcb1fab2 CPU:00 KER_CALL:THREAD_DESTROYALL/48 empty:0x00000000 empty:0x00000000
t:0xbcb1fcdb CPU:00 THREAD  :THDESTROY     pid:98319 tid:1
t:0xbcb20055 CPU:00 THREAD  :THDEAD        pid:98319 tid:1
t:0xbcb2021e CPU:00 THREAD  :THRUNNING     pid:7 tid:5
t:0xbcb21262 CPU:00 THREAD  :THREADY       pid:1 tid:5
t:0xbcb21d61 CPU:00 KER_EXIT:MSG_RECEIVEV/14 rcvid:0x00000000 rmsg:"" (0x00000000)
t:0xbcb234e8 CPU:00 INT_ENTR:0x00000000 (0) inkernel=0x00000001
t:0xbcb238b4 CPU:00 INT_EXIT:0x00000000 (0) inkernel=0x00000001
t:0xbcb2905f CPU:00 KER_CALL:INTERRUPT_UNMASK/60 intr:10 id:5
t:0xbcb297e2 CPU:00 KER_EXIT:INTERRUPT_UNMASK/60 mask_level:0x00000000 empty:0x00000000
t:0xbcb29d28 CPU:00 KER_CALL:MSG_RECEIVEV/14 chid:0x00000005 rparts:1
t:0xbcb29fca CPU:00 THREAD  :THRECEIVE     pid:7 tid:5
t:0xbcb2a177 CPU:00 THREAD  :THRUNNING     pid:7 tid:11
t:0xbcb2a4c8 CPU:00 KER_EXIT:SYNC_CONDVAR_WAIT/82 ret_val:0 empty:0x00000000
t:0xbcb2b8de CPU:00 KER_CALL:SYNC_CONDVAR_SIGNAL/83 sync_p:807144c all:0
t:0xbcb2bf6c CPU:00 THREAD  :THREADY       pid:7 tid:8
t:0xbcb2c256 CPU:00 KER_EXIT:SYNC_CONDVAR_SIG/83 ret_val:0 empty:0x00000000
t:0xbcb2c8ec CPU:00 KER_CALL:SYNC_CONDVAR_WAIT/82 sync_p:8071b90 mutex_p:8071b88
t:0xbcb2cdd4 CPU:00 THREAD  :THCONDVAR     pid:7 tid:11
t:0xbcb2cf82 CPU:00 THREAD  :THRUNNING     pid:1 tid:5
t:0xbcb2d438 CPU:00 INT_CALL:KER_MSG_RECEIVEV/14
t:0xbcb2e00c CPU:00 KER_CALL:RING0/02 func_p:ff836f16 arg_p:e3fd2ee0
t:0xbcb2e470 CPU:00 KER_EXIT:RING0/02 ret_val:0xe313c7b8 empty:0x00000000
t:0xbcb2e93c CPU:00 KER_CALL:RING0/02 func_p:ff83562c arg_p:e313c8ac
t:0xbcb2eb46 CPU:00 KER_EXIT:RING0/02 ret_val:0x00000002 empty:0x00000000
t:0xbcb2eee8 CPU:00 KER_CALL:RING0/02 func_p:ff836f16 arg_p:e3fd2e54
															.
															.
															.
t:0xbcd2a81c CPU:00 INT_ENTR:0x00000000 (0) inkernel=0x00000081
t:0xbcd2a9a4 CPU:00 INT_EXIT:0x00000000 (0) inkernel=0x00000081
t:0xbcd2ac29 CPU:00 KER_EXIT:RING0/02 ret_val:0x00000000 empty:0x00000000
t:0xbcd2ae9a CPU:00 KER_CALL:RING0/02 func_p:ff82874e arg_p:0

C File: one_class.c

/*
 * Copyright 2003, QNX Software Systems. All Rights Reserved.
 *
 * This source code may contain confidential information of QNX Software
 * Systems (QSS) and its licensors. Any use, reproduction,
 * modification, disclosure, distribution or transfer of this software,
 * or any software which includes or is based upon any of this code, is
 * prohibited unless expressly authorized by QSS by written agreement. For
 * more information (including whether this source code file has been
 * published) please email licensing@qnx.com.
 */

#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 deamon mode as:

	  tracelogger -n iter_number -d1

	  with iter_number = your choice of 1 through 10

	  After executing the example, the tracelogger (daemon)
	  will log the specified number of iterations and then
	  terminate. There are no messages printed uppon 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 "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.
	 * The number of full logged iterations is user specified.
	 */
	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);
}

Sample result file: one_class.results.txt

TRACEPRINTER version 0.97
TRACEPARSER LIBRARY version 0.98
 -- HEADER FILE INFORMATION -- 
       TRACE_FILE_NAME:: /dev/shmem/tracebuffer
            TRACE_DATE:: Fri Aug 17 09:15:34 2001
       TRACE_VER_MAJOR:: 0
       TRACE_VER_MINOR:: 97
   TRACE_LITTLE_ENDIAN:: TRUE
        TRACE_ENCODING:: 16 byte events
       TRACE_BOOT_DATE:: Fri Aug 17 09:02:16 2001
  TRACE_CYCLES_PER_SEC:: 132980400
         TRACE_CPU_NUM:: 1
         TRACE_SYSNAME:: QNX
        TRACE_NODENAME:: localhost
     TRACE_SYS_RELEASE:: 6.1.0
     TRACE_SYS_VERSION:: 2001/08/15-08:15:15
         TRACE_MACHINE:: x86pc
     TRACE_SYSPAGE_LEN:: 2248
 -- KERNEL EVENTS -- 
t:0x9bebdaf3 CPU:00 THREAD  :THCREATE      pid:1 tid:1
t:0x9bebdd74 CPU:00 THREAD  :THREADY       pid:1 tid:1
t:0x9bebde66 CPU:00 THREAD  :THCREATE      pid:1 tid:2
t:0x9bebdf46 CPU:00 THREAD  :THRECEIVE     pid:1 tid:2
t:0x9bebe05c CPU:00 THREAD  :THCREATE      pid:1 tid:3
															.
															.
															.
t:0x9bebe120 CPU:00 THREAD  :THRECEIVE     pid:1 tid:3
t:0x9bebe25e CPU:00 THREAD  :THCREATE      pid:1 tid:4
t:0x9bebe31c CPU:00 THREAD  :THRECEIVE     pid:1 tid:4
t:0x9bebe42c CPU:00 THREAD  :THCREATE      pid:1 tid:5
t:0x9bebe4ea CPU:00 THREAD  :THRECEIVE     pid:1 tid:5
t:0x9bebe5e4 CPU:00 THREAD  :THCREATE      pid:1 tid:6
t:0x9bebe6a2 CPU:00 THREAD  :THRECEIVE     pid:1 tid:6
t:0x9c436edf CPU:00 THREAD  :THREADY       pid:8 tid:5
															.
															.
															.
t:0x9c437a15 CPU:00 THREAD  :THRECEIVE     pid:7 tid:2
t:0x9c437be0 CPU:00 THREAD  :THRUNNING     pid:8 tid:5

C File: five_events.c

/*
 * Copyright 2003, QNX Software Systems. All Rights Reserved.
 *
 * This source code may contain confidential information of QNX Software
 * Systems (QSS) and its licensors. Any use, reproduction,
 * modification, disclosure, distribution or transfer of this software,
 * or any software which includes or is based upon any of this code, is
 * prohibited unless expressly authorized by QSS by written agreement. For
 * more information (including whether this source code file has been
 * published) please email licensing@qnx.com.
 */

#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 deamon mode as:

	  tracelogger -n iter_number -d1

	  with iter_number = your choice of 1 through 10

	  After executing the example, the tracelogger (daemon)
	  will log the specified number of iterations and then
	  terminate. There are no messages printed uppon 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.
	 * The number of full logged iterations is user specified.
	 */
	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);
}

Sample result file: five_events.results.txt

TRACEPRINTER version 0.97
TRACEPARSER LIBRARY version 0.98
 -- HEADER FILE INFORMATION -- 
       TRACE_FILE_NAME:: /dev/shmem/tracebuffer
            TRACE_DATE:: Fri Aug 17 09:15:51 2001
       TRACE_VER_MAJOR:: 0
       TRACE_VER_MINOR:: 97
   TRACE_LITTLE_ENDIAN:: TRUE
        TRACE_ENCODING:: 16 byte events
       TRACE_BOOT_DATE:: Fri Aug 17 09:02:16 2001
  TRACE_CYCLES_PER_SEC:: 132980400
         TRACE_CPU_NUM:: 1
         TRACE_SYSNAME:: QNX
        TRACE_NODENAME:: localhost
     TRACE_SYS_RELEASE:: 6.1.0
     TRACE_SYS_VERSION:: 2001/08/15-08:15:15
         TRACE_MACHINE:: x86pc
     TRACE_SYSPAGE_LEN:: 2248
 -- KERNEL EVENTS -- 
t:0x3abf47cf CPU:00 PROCESS :PROCCREATE_NAME
                      ppid:0
                       pid:1
                      name:/home/mmacies/instrumentation/x86/procnto-instr
t:0x3abf50b1 CPU:00 THREAD  :THCREATE      pid:1 tid:1
t:0x3abf5208 CPU:00 THREAD  :THCREATE      pid:1 tid:2
t:0x3abf5326 CPU:00 THREAD  :THCREATE      pid:1 tid:3
t:0x3abf546a CPU:00 THREAD  :THCREATE      pid:1 tid:4
t:0x3abf5554 CPU:00 THREAD  :THCREATE      pid:1 tid:5
t:0x3abf5654 CPU:00 THREAD  :THCREATE      pid:1 tid:6
t:0x3abf57d8 CPU:00 THREAD  :THCREATE      pid:1 tid:7
t:0x3abf58d8 CPU:00 THREAD  :THCREATE      pid:1 tid:8
															.
															.
															.
t:0x3abfd7da CPU:00 THREAD  :THRUNNING     pid:184335 tid:1
t:0x3abff400 CPU:00 THREAD  :THRUNNING     pid:7 tid:11
t:0x3ac02c55 CPU:00 THREAD  :THRUNNING     pid:1 tid:5
t:0x3ac051d8 CPU:00 THREAD  :THCREATE      pid:184335 tid:1
t:0x3ac0535b CPU:00 THREAD  :THRUNNING     pid:184335 tid:1
t:0x3ac0a687 CPU:00 THREAD  :THRUNNING     pid:4 tid:1
t:0x3ac0e597 CPU:00 KER_EXIT:MSG_READV/16
                    rbytes:47
                      rmsg:"" (0x6f72500a 0x73736563 0x34383120)
t:0x3ac1ad22 CPU:00 INT_ENTR:0x00000000 (0) inkernel=0x00000001
t:0x3ac3b3fc CPU:00 INT_ENTR:0x00000000 (0) inkernel=0x00000001
t:0x3ac5baba CPU:00 INT_ENTR:0x00000000 (0) inkernel=0x00000001
t:0x3ac5bf32 CPU:00 THREAD  :THRUNNING     pid:1 tid:5
t:0x3ac5c9f8 CPU:00 THREAD  :THRUNNING     pid:4 tid:1
															.
															.
															.
t:0x3b8a6de3 CPU:00 THREAD  :THRUNNING     pid:7 tid:11
t:0x3b8a7d4e CPU:00 INT_ENTR:0x00000000 (0) inkernel=0x00000001
t:0x3b8a984c CPU:00 THREAD  :THRUNNING     pid:7 tid:8

C File: ker_calls.c

/*
 * Copyright 2003, QNX Software Systems. All Rights Reserved.
 *
 * This source code may contain confidential information of QNX Software
 * Systems (QSS) and its licensors. Any use, reproduction,
 * modification, disclosure, distribution or transfer of this software,
 * or any software which includes or is based upon any of this code, is
 * prohibited unless expressly authorized by QSS by written agreement. For
 * more information (including whether this source code file has been
 * published) please email licensing@qnx.com.
 */

#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
	   (defult is all)

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

	  tracelogger -n iter_number -d1

	  with iter_number = your choice of 1 through 10

	  After executing the example, the tracelogger (daemon)
	  will log the specified number of iterations and then
	  terminate. There are no messages printed uppon 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 <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 - exitting\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.
	 * The number of full logged iterations is user specified.
	 */
	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);
}

Sample result file: ker_calls.all.results.txt

TRACEPRINTER version 0.97
TRACEPARSER LIBRARY version 0.98
 -- HEADER FILE INFORMATION -- 
       TRACE_FILE_NAME:: /dev/shmem/tracebuffer
            TRACE_DATE:: Fri Aug 17 09:17:00 2001
       TRACE_VER_MAJOR:: 0
       TRACE_VER_MINOR:: 97
   TRACE_LITTLE_ENDIAN:: TRUE
        TRACE_ENCODING:: 16 byte events
       TRACE_BOOT_DATE:: Fri Aug 17 09:02:16 2001
  TRACE_CYCLES_PER_SEC:: 132980400
         TRACE_CPU_NUM:: 1
         TRACE_SYSNAME:: QNX
        TRACE_NODENAME:: localhost
     TRACE_SYS_RELEASE:: 6.1.0
     TRACE_SYS_VERSION:: 2001/08/15-08:15:15
         TRACE_MACHINE:: x86pc
     TRACE_SYSPAGE_LEN:: 2248
 -- KERNEL EVENTS -- 
t:0x35b45a23 CPU:00 THREAD  :THCREATE      pid:1 tid:1
t:0x35b45b6e CPU:00 THREAD  :THREADY       pid:1 tid:1
t:0x35b45c86 CPU:00 THREAD  :THCREATE      pid:1 tid:2
															.
															.
															.
t:0x35b45d54 CPU:00 THREAD  :THRECEIVE     pid:1 tid:2
t:0x35b45e8c CPU:00 THREAD  :THCREATE      pid:1 tid:3
t:0x35b45f50 CPU:00 THREAD  :THRECEIVE     pid:1 tid:3
t:0x35b4608e CPU:00 THREAD  :THCREATE      pid:1 tid:4
t:0x35b4614c CPU:00 THREAD  :THRECEIVE     pid:1 tid:4
t:0x35b4622e CPU:00 THREAD  :THCREATE      pid:1 tid:5
t:0x35b462ec CPU:00 THREAD  :THRECEIVE     pid:1 tid:5
t:0x35b463e6 CPU:00 THREAD  :THCREATE      pid:1 tid:6
t:0x35b464a4 CPU:00 THREAD  :THRECEIVE     pid:1 tid:6
t:0x35b4663a CPU:00 THREAD  :THCREATE      pid:1 tid:7
t:0x35b466f8 CPU:00 THREAD  :THRECEIVE     pid:1 tid:7
t:0x35b467f2 CPU:00 THREAD  :THCREATE      pid:1 tid:8
t:0x35b468b0 CPU:00 THREAD  :THRECEIVE     pid:1 tid:8
t:0x35b46b20 CPU:00 THREAD  :THCREATE      pid:2 tid:1
															.
															.
															.
t:0x35bbdee9 CPU:00 THREAD  :THREADY       pid:4 tid:1
t:0x35bbe032 CPU:00 THREAD  :THRUNNING     pid:1 tid:5
t:0x35bbe97a CPU:00 KER_CALL:MSG_RECEIVEV/14 chid:0x00000001 rparts:2080
t:0x35bbec68 CPU:00 THREAD  :THRECEIVE     pid:1 tid:5
t:0x35bbee10 CPU:00 THREAD  :THRUNNING     pid:4 tid:1
t:0x35c2f825 CPU:00 THREAD  :THREADY       pid:208911 tid:1
t:0x35c2ff68 CPU:00 KER_CALL:MSG_RECEIVEV/14 chid:0x00000001 rparts:2077
t:0x35c30190 CPU:00 THREAD  :THRECEIVE     pid:4 tid:1
t:0x35c302c6 CPU:00 THREAD  :THRUNNING     pid:208911 tid:1
t:0x35c32979 CPU:00 THREAD  :THREPLY       pid:208911 tid:1
t:0x35c32c6f CPU:00 THREAD  :THRUNNING     pid:4 tid:1
t:0x35c33487 CPU:00 KER_EXIT:MSG_RECEIVEV/14
                     rcvid:0x00000012
                      rmsg:"" (0x00040116 0x0000002d 0x00000000)
                  info->nd:0
               info->srcnd:0
                 info->pid:208911
                 info->tid:1
                info->chid:1
               info->scoid:1073741842
                info->coid:0
              info->msglen:4
           info->srcmsglen:4
           info->dstmsglen:2147483647
            info->priority:15
               info->flags:0
            info->reserved:0
t:0x35c35919 CPU:00 THREAD  :THREADY       pid:208911 tid:1
t:0x35c36032 CPU:00 KER_CALL:MSG_RECEIVEV/14 chid:0x00000001 rparts:2077
															.
															.
															.
t:0x35da1b25 CPU:00 THREAD  :THRUNNING     pid:7 tid:5
t:0x35da1c4e CPU:00 THREAD  :THREADY       pid:1 tid:1

Sample result file: ker_calls.14.results.txt

TRACEPRINTER version 0.97
TRACEPARSER LIBRARY version 0.98
 -- HEADER FILE INFORMATION -- 
       TRACE_FILE_NAME:: /dev/shmem/tracebuffer
            TRACE_DATE:: Wed Aug 22 09:52:49 2001
       TRACE_VER_MAJOR:: 0
       TRACE_VER_MINOR:: 97
   TRACE_LITTLE_ENDIAN:: TRUE
        TRACE_ENCODING:: 16 byte events
       TRACE_BOOT_DATE:: Tue Aug 21 14:03:25 2001
  TRACE_CYCLES_PER_SEC:: 132961600
         TRACE_CPU_NUM:: 1
         TRACE_SYSNAME:: QNX
        TRACE_NODENAME:: localhost
     TRACE_SYS_RELEASE:: 6.1.0
     TRACE_SYS_VERSION:: 2001/08/21-14:05:41
         TRACE_MACHINE:: x86pc
     TRACE_SYSPAGE_LEN:: 2248
 -- KERNEL EVENTS -- 
t:0x4c091677 CPU:00 THREAD  :THCREATE      pid:1 tid:1
t:0x4c0917ec CPU:00 THREAD  :THREADY       pid:1 tid:1
t:0x4c098b66 CPU:00 THREAD  :THDEAD        pid:12302 tid:1
                    .
                    .
                    .
t:0x4c099ed2 CPU:00 THREAD  :THREADY       pid:1 tid:1
t:0x4c09a422 CPU:00 INT_CALL:KER_MSG_RECEIVEV/14
t:0x4c09c872 CPU:00 THREAD  :THCREATE      pid:12302 tid:1
t:0x4c09c97c CPU:00 THREAD  :THWAITTHREAD  pid:1 tid:2
t:0x4c09cabf CPU:00 THREAD  :THRUNNING     pid:12302 tid:1
t:0x4c09d17c CPU:00 THREAD  :THREADY       pid:1 tid:2
t:0x4c0a13db CPU:00 THREAD  :THREPLY       pid:12302 tid:1
t:0x4c0a1618 CPU:00 THREAD  :THREADY       pid:4 tid:1
t:0x4c0a1786 CPU:00 THREAD  :THRUNNING     pid:4 tid:1
t:0x4c0a205f CPU:00 KER_EXIT:MSG_RECEIVEV/14
                     rcvid:0x00000011
                      rmsg:"" (0x00100102 0x0000002c 0x00000000)
                  info->nd:0
               info->srcnd:0
                 info->pid:12302
                 info->tid:1
                info->chid:1
               info->scoid:1073741841
                info->coid:2
              info->msglen:60
           info->srcmsglen:60
           info->dstmsglen:2147483647
            info->priority:15
               info->flags:0
            info->reserved:0
t:0x4c0b89e9 CPU:00 THREAD  :THREADY       pid:4 tid:1
t:0x4c0b8b2e CPU:00 THREAD  :THRUNNING     pid:1 tid:2
                    .
                    .
                    .
t:0x5a0dc58d CPU:00 THREAD  :THRUNNING     pid:7 tid:6
t:0x5a0dc6d0 CPU:00 THREAD  :THREADY       pid:1 tid:1
t:0x5a0dcb88 CPU:00 KER_EXIT:MSG_RECEIVEV/14
                     rcvid:0x00000000
                      rmsg:"" (0x00000000 0x00000000 0x00000030)
                  info->nd:0
               info->srcnd:0
                 info->pid:0
                 info->tid:0
                info->chid:0
               info->scoid:0
                info->coid:0
              info->msglen:0
           info->srcmsglen:0
           info->dstmsglen:0
            info->priority:0
               info->flags:0
            info->reserved:0
t:0x5a0dd3f8 CPU:00 KER_CALL:MSG_RECEIVEV/14 chid:0x00000009 rparts:16
t:0x5a0dd58a CPU:00 THREAD  :THRECEIVE     pid:7 tid:6
t:0x5a0dd6f6 CPU:00 THREAD  :THRUNNING     pid:1 tid:1

C File: eh_simple.c

/*
 * Copyright 2003, QNX Software Systems. All Rights Reserved.
 *
 * This source code may contain confidential information of QNX Software
 * Systems (QSS) and its licensors. Any use, reproduction,
 * modification, disclosure, distribution or transfer of this software,
 * or any software which includes or is based upon any of this code, is
 * prohibited unless expressly authorized by QSS by written agreement. For
 * more information (including whether this source code file has been
 * published) please email licensing@qnx.com.
 */

#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 deamon mode as:

	  tracelogger -n 1 -d1

	  After executing the example, the tracelogger (daemon)
	  will log the specified number of iterations and then
	  terminate. There are no messages printed uppon 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 <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 "ring0" 
 * from the _NTO_TRACE_KERCALL class.
 */
int call_ring0_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]: Fail to obtain I/O privileges - root privileges\n");

		return (-1);
	}

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

	/*
	 * Add event handler to the event "ring0"
	 * from _NTO_TRACE_KERCALL class.
	 */
	TRACE_EVENT
	(
	 argv[0],
	 TraceEvent(_NTO_TRACE_ADDEVENTHANDLER, 
                    _NTO_TRACE_KERCALLENTER, __KER_RING0, call_ring0_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 full logged iterations has been specified
	 * to be 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 iterration (-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_RING0)
	);
	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);
}

Sample result file: eh_sample.results.txt

TRACEPRINTER version 0.97
TRACEPARSER LIBRARY version 0.98
 -- HEADER FILE INFORMATION -- 
       TRACE_FILE_NAME:: /dev/shmem/tracebuffer
            TRACE_DATE:: Fri Aug 17 09:18:04 2001
       TRACE_VER_MAJOR:: 0
       TRACE_VER_MINOR:: 97
   TRACE_LITTLE_ENDIAN:: TRUE
        TRACE_ENCODING:: 16 byte events
       TRACE_BOOT_DATE:: Fri Aug 17 09:02:16 2001
  TRACE_CYCLES_PER_SEC:: 132980400
         TRACE_CPU_NUM:: 1
         TRACE_SYSNAME:: QNX
        TRACE_NODENAME:: localhost
     TRACE_SYS_RELEASE:: 6.1.0
     TRACE_SYS_VERSION:: 2001/08/15-08:15:15
         TRACE_MACHINE:: x86pc
     TRACE_SYSPAGE_LEN:: 2248
 -- KERNEL EVENTS -- 
															.
															.
															.
t:0x31ea0f3d CPU:00 THREAD  :THRUNNING     pid:245775 tid:1
t:0x31ebec31 CPU:00 KER_CALL:RING0/02 func_p:ff82874e arg_p:0
t:0x31eca36f CPU:00 THREAD  :THRUNNING     pid:7 tid:5
t:0x31eea437 CPU:00 KER_CALL:RING0/02 func_p:ff82874e arg_p:0
t:0x31ef5e6d CPU:00 THREAD  :THRUNNING     pid:7 tid:5
t:0x31f15ab9 CPU:00 KER_CALL:RING0/02 func_p:ff82874e arg_p:0
t:0x31f21f4f CPU:00 THREAD  :THRUNNING     pid:7 tid:5
t:0x31f41a0b CPU:00 KER_CALL:RING0/02 func_p:ff82874e arg_p:0
t:0x31f4dfa9 CPU:00 THREAD  :THRUNNING     pid:7 tid:5
t:0x31f6d8a7 CPU:00 KER_CALL:RING0/02 func_p:ff82874e arg_p:0
t:0x31f79c47 CPU:00 THREAD  :THRUNNING     pid:7 tid:5
t:0x31f99525 CPU:00 KER_CALL:RING0/02 func_p:ff82874e arg_p:0
t:0x31fa5d5f CPU:00 THREAD  :THRUNNING     pid:7 tid:5
t:0x31fc59a9 CPU:00 KER_CALL:RING0/02 func_p:ff82874e arg_p:0
t:0x31fd2879 CPU:00 THREAD  :THRUNNING     pid:7 tid:5
t:0x31ff2137 CPU:00 KER_CALL:RING0/02 func_p:ff82874e arg_p:0
t:0x31fffe11 CPU:00 THREAD  :THRUNNING     pid:7 tid:5
t:0x32031b27 CPU:00 KER_CALL:RING0/02 func_p:ff836f16 arg_p:e3ff5e9c
t:0x3203584f CPU:00 THREAD  :THRUNNING     pid:98317 tid:1
t:0x3204df2d CPU:00 KER_CALL:RING0/02 func_p:ff82874e arg_p:0
t:0x32058db7 CPU:00 THREAD  :THRUNNING     pid:7 tid:5
t:0x32078fcd CPU:00 KER_CALL:RING0/02 func_p:ff82874e arg_p:0
t:0x32084dbb CPU:00 THREAD  :THRUNNING     pid:7 tid:5
t:0x320a471b CPU:00 KER_CALL:RING0/02 func_p:ff82874e arg_p:0
t:0x320c3501 CPU:00 THREAD  :THRUNNING     pid:7 tid:5
t:0x320e2ebd CPU:00 KER_CALL:RING0/02 func_p:ff82874e arg_p:0
															.
															.
															.
t:0x35e2c6cf CPU:00 KER_CALL:RING0/02 func_p:ff82874e arg_p:0
t:0x35e38657 CPU:00 THREAD  :THRUNNING     pid:7 tid:5
t:0x35e59269 CPU:00 KER_CALL:RING0/02 func_p:ff82874e arg_p:0
t:0x35e6766d CPU:00 THREAD  :THRUNNING     pid:7 tid:5

C File: usr_event_simple.c

/*
 * Copyright 2003, QNX Software Systems. All Rights Reserved.
 *
 * This source code may contain confidential information of QNX Software
 * Systems (QSS) and its licensors. Any use, reproduction,
 * modification, disclosure, distribution or transfer of this software,
 * or any software which includes or is based upon any of this code, is
 * prohibited unless expressly authorized by QSS by written agreement. For
 * more information (including whether this source code file has been
 * published) please email licensing@qnx.com.
 */

#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 deamon mode as:

	  tracelogger -n iter_number -d1

	  with iter_number = your choice of 1 through 10

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

	  See accompanied documentation and comments within
	  the example 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.
	 * The number of full logged iterations is user specified.
	 */
	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 id(s): 111, 222, 333, 444 and 555
	 * (possible values are in the range 0...1023).
	 * Every user event with id=(111, ..., 555) has attached
	 * two numerical data (simple event): ({1,11}, ..., {4,44})
	 * and string (string event id=555) "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);
}

Sample result file: usr_event_simple.results.txt

TRACEPRINTER version 1.02
TRACEPARSER LIBRARY version 1.02
 -- HEADER FILE INFORMATION -- 
       TRACE_FILE_NAME:: /dev/shmem/tracebuffer
            TRACE_DATE:: Mon Apr 25 05:37:55 1988
       TRACE_VER_MAJOR:: 1
       TRACE_VER_MINOR:: 02
   TRACE_LITTLE_ENDIAN:: TRUE
        TRACE_ENCODING:: 16 byte events
       TRACE_BOOT_DATE:: Mon Apr 25 02:28:06 1988
  TRACE_CYCLES_PER_SEC:: 400013900
         TRACE_CPU_NUM:: 2
         TRACE_SYSNAME:: QNX
        TRACE_NODENAME:: localhost
     TRACE_SYS_RELEASE:: 6.2.1
     TRACE_SYS_VERSION:: 2002/12/09-10:13:08est
         TRACE_MACHINE:: x86pc
     TRACE_SYSPAGE_LEN:: 2400
 -- KERNEL EVENTS -- 
t:0x74a43dfa CPU:01 CONTROL :TIME msb:0x00000427, lsb(offset):0x74a43cb6
                             .
                             .
                             .
t:0x74a4d699 CPU:01 PROCESS :PROCCREATE_NAME
                      ppid:10
                       pid:28686
name:/cvs/utils/t/traceprinter/examples/usr_event_simple/nto/x86/o/examples-usr_event_simple
t:0x74a4dcb2 CPU:01 THREAD  :THCREATE      pid:28686 tid:1
t:0x74a4ddb7 CPU:01 THREAD  :THRUNNING     pid:28686 tid:1
t:0x74a4e0a8 CPU:01 KER_EXIT:TRACE_EVENT/01 ret_val:0x00000000 empty:0x00000000
t:0x74a4e3a2 CPU:01 KER_CALL:TRACE_EVENT/01 mode:0x4000001e class[header]:0x0000006f
t:0x74a4e4f1 CPU:01 USREVENT:EVENT:111, d0:0x00000001 d1:0x0000000b
t:0x74a4e650 CPU:01 KER_EXIT:TRACE_EVENT/01 ret_val:0x00000000 empty:0x00000000
t:0x74a4e8e5 CPU:01 KER_CALL:TRACE_EVENT/01 mode:0x4000001e class[header]:0x000000de
t:0x74a4e9dc CPU:01 USREVENT:EVENT:222, d0:0x00000002 d1:0x00000016
t:0x74a4eb51 CPU:01 KER_EXIT:TRACE_EVENT/01 ret_val:0x00000000 empty:0x00000000
t:0x74a4ee23 CPU:01 KER_CALL:TRACE_EVENT/01 mode:0x4000001e class[header]:0x0000014d
t:0x74a4ef07 CPU:01 USREVENT:EVENT:333, d0:0x00000003 d1:0x00000021
t:0x74a4f07c CPU:01 KER_EXIT:TRACE_EVENT/01 ret_val:0x00000000 empty:0x00000000
t:0x74a4f300 CPU:01 KER_CALL:TRACE_EVENT/01 mode:0x4000001e class[header]:0x000001bc
t:0x74a4f41e CPU:01 USREVENT:EVENT:444, d0:0x00000004 d1:0x0000002c
t:0x74a4f58a CPU:01 KER_EXIT:TRACE_EVENT/01 ret_val:0x00000000 empty:0x00000000
t:0x74a4f826 CPU:01 KER_CALL:TRACE_EVENT/01 mode:0x30000020 class[header]:0x0000022b
t:0x74a4fa4f CPU:01 USREVENT:EVENT:555 STR:"Hello world"
t:0x74a4fc63 CPU:01 KER_EXIT:TRACE_EVENT/01 ret_val:0x00000000 empty:0x00000000
                             .
                             .
                             .