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