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