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, tracelogger
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
...