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.