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

...