This chapter leads you through some tutorials to help you learn how to use TraceEvent() to control event tracing. It includes:
These tutorials all follow the same general procedure:
The default number of buffers is 32, which produces a rather large file, so we'll use the -n option to limit the number of buffers to a reasonable number. Feel free to use the default, but expect a large file.
If you don't want to run the program, take a look at our traceprinter output. (Note that different versions and systems will create slightly different results.)
You may include these samples in your code as long as you comply with the license agreement. |
To reduce repetition and keep the programs simple, we've put some functionality into a header file, instrex.h:
/* * $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. * $ */ /* * instrex.h instrumentation examples - public definitions * */ #ifndef __INSTREX_H_INCLUDED #include <errno.h> #include <stdio.h> #include <string.h> /* * Supporting macro that intercepts and prints a possible * error state during calling TraceEvent(...) * * Call TRACE_EVENT(TraceEvent(...)) <=> TraceEvent(...) * */ #define TRACE_EVENT(prog_name, trace_event) \ if((int)((trace_event))==(-1)) \ { \ (void) fprintf \ ( \ stderr, \ "%s: line:%d function call TraceEvent() failed, errno(%d): %s\n", \ prog_name, \ __LINE__, \ errno, \ strerror(errno) \ ); \ \ return (-1); \ } /* * Prints error message */ #define TRACE_ERROR_MSG(prog_name, msg) \ (void) fprintf(stderr,"%s: %s\n", prog_name, msg) #define __INSTREX_H_INCLUDED #endif
You'll have to save instrex.h in the same directory as the C code in order to compile the programs.
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, 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 "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.
Now we'll gather all events from only one class, _NTO_TRACE_THREAD. This class is arbitrarily chosen to demonstrate filtering by classes; there's nothing particularly special about this class versus any other. For a full list of the possible classes, see “Classes and events” in the Events and the Kernel chapter in this guide.
Here's the source, one_class.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 events from the thread class (_NTO_TRACE_THREAD) are monitored (intercepted). 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 "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)); /* * Intercept only thread events */ TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_ADDCLASS, _NTO_TRACE_THREAD)); /* * Start tracing process * * During the tracing process, the tracelogger (which * is being executed in 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 one_class.kev
and run the compiled program in another:
./one_class
The trace data is in one_class.kev; to examine it, type:
traceprinter -f one_class.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:: one_class.kev TRACE_DATE:: Wed Jun 24 10:55:05 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 one_class.kev -- KERNEL EVENTS -- t:0x002c4d55 CPU:00 CONTROL: BUFFER sequence = 37, num_events = 714 t:0x002c4d55 CPU:00 THREAD :THCREATE pid:1 tid:1 t:0x002c5531 CPU:00 THREAD :THREADY pid:1 tid:1 priority:0 policy:1 t:0x002c5bbe CPU:00 THREAD :THCREATE pid:1 tid:2 t:0x002c5cd2 CPU:00 THREAD :THRECEIVE pid:1 tid:2 priority:255 policy:2 t:0x002c6185 CPU:00 THREAD :THCREATE pid:1 tid:3 t:0x002c6272 CPU:00 THREAD :THRECEIVE pid:1 tid:3 priority:255 policy:2 t:0x002c64eb CPU:00 THREAD :THCREATE pid:1 tid:4 t:0x002c65d8 CPU:00 THREAD :THRECEIVE pid:1 tid:4 priority:10 policy:2 t:0x002c67fc CPU:00 THREAD :THCREATE pid:1 tid:5 t:0x002c68ea CPU:00 THREAD :THRECEIVE pid:1 tid:5 priority:255 policy:2 t:0x002c6bae CPU:00 THREAD :THCREATE pid:1 tid:7 t:0x002c6c9b CPU:00 THREAD :THRECEIVE pid:1 tid:7 priority:10 policy:2 t:0x002c6f03 CPU:00 THREAD :THCREATE pid:1 tid:8 t:0x002c6ff0 CPU:00 THREAD :THRECEIVE pid:1 tid:8 priority:10 policy:2 t:0x002c72ec CPU:00 THREAD :THCREATE pid:1 tid:10 t:0x002c73d9 CPU:00 THREAD :THRECEIVE pid:1 tid:10 priority:10 policy:2 t:0x002c7665 CPU:00 THREAD :THCREATE pid:1 tid:11 t:0x002c7752 CPU:00 THREAD :THRECEIVE pid:1 tid:11 priority:10 policy:2 t:0x002c7a9d CPU:00 THREAD :THCREATE pid:1 tid:12 t:0x002c7b8a CPU:00 THREAD :THRECEIVE pid:1 tid:12 priority:10 policy:2 t:0x002c7e44 CPU:00 THREAD :THCREATE pid:1 tid:15 t:0x002c7f31 CPU:00 THREAD :THRECEIVE pid:1 tid:15 priority:10 policy:2 t:0x002c81a2 CPU:00 THREAD :THCREATE pid:1 tid:20 t:0x002c828f CPU:00 THREAD :THRECEIVE pid:1 tid:20 priority:10 policy:2 t:0x002c88e3 CPU:00 THREAD :THCREATE pid:2 tid:1 t:0x002c89d3 CPU:00 THREAD :THREPLY pid:2 tid:1 priority:10 policy:3 t:0x002c8fad CPU:00 THREAD :THCREATE pid:4099 tid:1 t:0x002c909a CPU:00 THREAD :THRECEIVE pid:4099 tid:1 priority:10 policy:3 t:0x002c95b7 CPU:00 THREAD :THCREATE pid:4100 tid:1 t:0x002c96a4 CPU:00 THREAD :THRECEIVE pid:4100 tid:1 priority:10 policy:3 t:0x002c9b6e CPU:00 THREAD :THCREATE pid:4101 tid:1 t:0x002c9ccd CPU:00 THREAD :THSIGWAITINFO pid:4101 tid:1 priority:10 policy:3 ...
Notice that we've significantly reduced the amount of output.
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.
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 ...
In this example, we intercept two events from two different classes. Each event has an event handler attached to it; the event handlers are closing and opening the stream. Here's the source, eh_simple.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. Two events from two classes are included and monitored interchangeably. The flow control of monitoring the specified events is controlled with attached event handlers. In order to use this example, start the tracelogger in the daemon mode as: tracelogger -n 1 -d1 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 <unistd.h> #include <sys/trace.h> #include <sys/kercalls.h> #include "instrex.h" /* * Prepare event structure where the event data will be * stored and passed to an event handler. */ event_data_t e_d_1; _Uint32t data_array_1[20]; /* 20 elements for potential args. */ event_data_t e_d_2; _Uint32t data_array_2[20]; /* 20 elements for potential args. */ /* * Global state variable that controls the * event flow between two events */ int g_state; /* * Event handler attached to the event __KER_MSG_SENDV * from the _NTO_TRACE_KERCALL class. */ int call_msg_send_eh(event_data_t* e_d) { if(g_state) { g_state = !g_state; return (1); } return (0); } /* * Event handler attached to the event _NTO_TRACE_THRUNNING * from the _NTO_TRACE_THREAD (thread) class. */ int thread_run_eh(event_data_t* e_d) { if(!g_state) { g_state = !g_state; return (1); } return (0); } int main(int argc, char **argv) { /* * First fill arrays inside event data structures */ e_d_1.data_array = data_array_1; e_d_2.data_array = data_array_2; /* * 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 */ TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_SETALLCLASSESFAST)); /* * Obtain I/O privileges before adding event handlers */ if (ThreadCtl(_NTO_TCTL_IO, 0)!=EOK) { /* obtain I/O privileges */ (void) fprintf(stderr, "argv[0]: Failed to obtain I/O privileges\n"); return (-1); } /* * Intercept one event from class _NTO_TRACE_KERCALL, * event __KER_MSG_SENDV. */ TRACE_EVENT ( argv[0], TraceEvent(_NTO_TRACE_ADDEVENT, _NTO_TRACE_KERCALLENTER, __KER_MSG_SENDV) ); /* * Add event handler to the event __KER_MSG_SENDV * from _NTO_TRACE_KERCALL class. */ TRACE_EVENT ( argv[0], TraceEvent(_NTO_TRACE_ADDEVENTHANDLER, _NTO_TRACE_KERCALLENTER, __KER_MSG_SENDV, call_msg_send_eh, &e_d_1) ); /* * Intercept one event from class _NTO_TRACE_THREAD */ TRACE_EVENT ( argv[0], TraceEvent(_NTO_TRACE_ADDEVENT, _NTO_TRACE_THREAD, _NTO_TRACE_THRUNNING) ); /* * Add event event handler to the _NTO_TRACE_THRUNNING event * from the _NTO_TRACE_THREAD (thread) class. */ TRACE_EVENT ( argv[0], TraceEvent(_NTO_TRACE_ADDEVENTHANDLER, _NTO_TRACE_THREAD, _NTO_TRACE_THRUNNING, thread_run_eh, &e_d_2) ); /* * Start tracing process * * During the tracing process, the tracelogger (which * is being executed in a daemon mode) will log all events. * The number of iterations has been specified as 1. */ TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_START)); /* * During one second collect all events */ (void) sleep(1); /* * Stop tracing process by closing the event stream. */ TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_STOP)); /* * Flush the internal buffer since the number * of stored events could be less than * "high water mark" of one buffer (715 events). * * The tracelogger will probably terminate at * this point, since it has been executed with * one iteration (-n 1 option). */ TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_FLUSHBUFFER)); /* * Delete event handlers before exiting to avoid execution * in the missing address space. */ TRACE_EVENT ( argv[0], TraceEvent(_NTO_TRACE_DELEVENTHANDLER, _NTO_TRACE_KERCALLENTER, __KER_MSG_SENDV) ); TRACE_EVENT ( argv[0], TraceEvent(_NTO_TRACE_DELEVENTHANDLER, _NTO_TRACE_THREAD, _NTO_TRACE_THRUNNING) ); /* * Wait one second before terminating to hold the address space * of the event handlers. */ (void) sleep(1); return (0); }
Compile it, and then run tracelogger in one window:
tracelogger -d1 -n 1 -f eh_simple.kev
For this example, we've specified the number of iterations to be 1. |
Run the compiled program in another window:
./eh_simple
The trace data is in eh_simple.kev; to examine it, type:
traceprinter -f eh_simple.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:: eh_simple.kev TRACE_DATE:: Wed Jun 24 10:58:41 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 1 -f eh_simple.kev -- KERNEL EVENTS -- t:0x33139a74 CPU:00 CONTROL: BUFFER sequence = 53, num_events = 482 t:0x33139a74 CPU:00 THREAD :THRUNNING pid:1749040 tid:1 t:0x362d0710 CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000003 msg:"" (0x00100102) t:0x362d1d04 CPU:00 THREAD :THRUNNING pid:217117 tid:1 t:0x362e8e3e CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000000 msg:"" (0x00200113) t:0x362ea264 CPU:00 THREAD :THRUNNING pid:4102 tid:8 t:0x362f1248 CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000003 msg:"" (0x00000106) t:0x362f1c67 CPU:00 THREAD :THRUNNING pid:217117 tid:1 t:0x362fd08b CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000003 msg:"" (0x00100102) t:0x362fd949 CPU:00 THREAD :THRUNNING pid:217117 tid:1 t:0x36305424 CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000003 msg:"" (0x00000106) t:0x36305e35 CPU:00 THREAD :THRUNNING pid:217117 tid:1 t:0x3630a572 CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000003 msg:"" (0x00000106) t:0x3630aeb7 CPU:00 THREAD :THRUNNING pid:217117 tid:1 t:0x3631bd5b CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000003 msg:"" (0x00100102) t:0x3631c6aa CPU:00 THREAD :THRUNNING pid:217117 tid:1 t:0x363253bb CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000003 msg:"" (0x00000106) t:0x36325d95 CPU:00 THREAD :THRUNNING pid:217117 tid:1 t:0x369b2349 CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000003 msg:"" (0x00000106) t:0x369b2bbe CPU:00 THREAD :THRUNNING pid:217117 tid:1 t:0x369b88d8 CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000007 msg:"" (0x00100106) t:0x369b974a CPU:00 THREAD :THRUNNING pid:1 tid:15 t:0x369c48ab CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000008 msg:"" (0x00100106) t:0x369c53db CPU:00 THREAD :THRUNNING pid:126997 tid:2 t:0x369cee17 CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000008 msg:"" (0x00100106) t:0x369cf533 CPU:00 THREAD :THRUNNING pid:126997 tid:2 t:0x369d82b6 CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000009 msg:"" (0x00100106) t:0x369d9178 CPU:00 THREAD :THRUNNING pid:8200 tid:10 t:0x369eae84 CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000006 msg:"" (0x00020100) t:0x369eb687 CPU:00 THREAD :THRUNNING pid:1 tid:15 t:0x369f56b1 CPU:00 KER_CALL:MSG_SENDV/11 coid:0x00000006 msg:"" (0x00020100) ...
This is an important example because it demonstrates the use of the dynamic rules filter to perform tasks beyond basic filtering.
This example demonstrates the insertion of a user event into the event stream. Here's the source, usr_event_simple.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. Additionally, four user-generated simple events and one string event are intercepted. 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. The intercepted user events (class USREVENT) have event IDs (EVENT) equal to: 111, 222, 333, 444 and 555. See accompanied documentation and comments within the sample source code for more explanations. #endif #include <sys/trace.h> #include <unistd.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. */ 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)); /* * Insert four user-defined simple events and one string * event into the event stream. The user events have * arbitrary event IDs: 111, 222, 333, 444, and 555 * (possible values are in the range 0...1023). * The user events with ID=(111, ..., 444) are simple events * that have two numbers attached: ({1,11}, ..., {4,44}). * The user string event (ID 555) includes the string, * "Hello world". */ TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_INSERTSUSEREVENT, 111, 1, 11)); TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_INSERTSUSEREVENT, 222, 2, 22)); TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_INSERTSUSEREVENT, 333, 3, 33)); TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_INSERTSUSEREVENT, 444, 4, 44)); TRACE_EVENT(argv[0], TraceEvent(_NTO_TRACE_INSERTUSRSTREVENT,555, "Hello world" )); /* * 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 usr_event_simple.kev
and run the compiled program in another:
./usr_event_simple
The trace data is in usr_event_simple.kev; to examine it, type:
traceprinter -f usr_event_simple.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:: usr_event_simple.kev TRACE_DATE:: Wed Jun 24 10:59:34 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 usr_event_simple.kev -- KERNEL EVENTS -- t:0x254620e4 CPU:00 CONTROL: BUFFER sequence = 54, num_events = 714 ... t:0x25496c81 CPU:00 PROCESS :PROCCREATE_NAME ppid:426022 pid:1810480 name:./usr_event_simple t:0x2549701a CPU:00 THREAD :THCREATE pid:1810480 tid:1 t:0x25497112 CPU:00 THREAD :THRUNNING pid:1810480 tid:1 t:0x2549793a CPU:00 KER_EXIT:TRACE_EVENT/01 ret_val:0x00000000 empty:0x00000000 t:0x25497f48 CPU:00 USREVENT:EVENT:111, d0:0x00000001 d1:0x0000000b t:0x254982c5 CPU:00 USREVENT:EVENT:222, d0:0x00000002 d1:0x00000016 t:0x25498638 CPU:00 USREVENT:EVENT:333, d0:0x00000003 d1:0x00000021 t:0x25498996 CPU:00 USREVENT:EVENT:444, d0:0x00000004 d1:0x0000002c t:0x25499451 CPU:00 USREVENT:EVENT:555 STR:"Hello world" t:0x2549bde5 CPU:00 KER_CALL:THREAD_DESTROY/47 tid:-1 status_p:0 t:0x2549d0d6 CPU:00 KER_EXIT:THREAD_DESTROY/47 ret_val:0x00000030 empty:0x00000000 t:0x2549d8ae CPU:00 KER_CALL:THREAD_DESTROYALL/48 empty:0x00000000 empty:0x00000000 ...
Inserting your own events lets you flag events or bracket groups of events to isolate them for study. It's also useful for inserting internal, customized information into the event stream.