Measuring Execution Time with Kernel profiling ?

juliantcp · February 21, 2006, 8:29am

I would like to insert marks before and after a function, in order to measure execution time with the kernel profiler.

The help on qnx 6.3 says that :

“”"
In addition, the Instrumented Kernel also inserts “artificial” events for:

Time events
User events that may be used as “marker flags”
“”"

I don’t find if it is possible to insert such “marker flags” on the developped application.

How to do it ?

rgallen · February 21, 2006, 4:46pm

I think the text you are referring to, is explaining that the kernel inserts some “extraneous” stuff in the trace file, in order to help the analysis tool. I don’t believe it is suggesting that you have control over this (precisely the opposite, I think).

However, you can insert your own events into the trace using the TraceEvent() API. I believe it is exactly what you are looking for. It is actually very well documented.

Rennie

juliantcp · February 23, 2006, 11:15am

Right, thank you. I did not find it, because there is two versions of the TraceEvent() function on the Qnx Help, I was reading the other one.

Do you know if the IDE is able show and process this user events on the views like “Trace Event Log”, “Condition Statistics” ???

Many thanks,

JuliÃ¡n

cburgess · February 27, 2006, 3:31pm

The IDE will display your user events, although it tries to figure out whether they are text or hex, and sometimes gets it wrong. It’s rule of thumb is that printable data greater than 8 bytes is a string.

You can search for user events so you can use the condition statistics.

Note that user event codes should be between 0 and 0x3ff

juliantcp · February 28, 2006, 11:50am

Hello,

Now I am able to detect the user events on the “Condition Statistics” view (defining a condition of the class “User events”, Code “All User Events”.

I also see the event “TraceEvent Enter” and “Event Code 0x00000000” on the “General Statistics View” (“Events” Window). Is it this ??

But I am not able to see them on the “Trace Event Log” view !

Anyway, is there a way from the IDE to only select this events, with the associated time, and save the information in a cvs like file ?? Or should I do a specific programm for this ?

I have generated the user event with this two calls:

TraceEvent(_NTO_TRACE_INSERTSUSEREVENT, _NTO_TRACE_USERFIRST, 0, 0);

TraceEvent(_NTO_TRACE_INSERTSUSEREVENT, _NTO_TRACE_USERFIRST, 1, 0);

cburgess · February 28, 2006, 2:27pm

Is this SP1 or SP2

You should be able to select an event filter and select only user events (right click menu on timeline)

If you don’t want any non user events in the log though why not use

TraceEvent( _NTO_TRACE_DELALLCLASSES );
TraceEvent( _NTO_TRACE_ADDCLASS, _NTO_TRACE_CONTROL ); /* for time wrap events */

(user events will still be logged)

juliantcp · March 1, 2006, 3:47pm

First at all: Thank you.

It is SP2.

Fine! It works !!

And with this I am able to get prefectly the events on the “Trace Event Log” view.

Now I would like to save this log on a .cvs like file, in order to calculate the elpased time from excell. Or even better, calculate this time directy with the IDE.

But I am not able to save this filtered events on a file. Is it possible ?

So a specific self-made utility is needed in order to extract this events directly from the .kev file ??

Best regards,

JuliÃ¡n

cburgess · March 1, 2006, 4:37pm

With the filter on, click the File->Save As and you will be able to save only the filtered events.
Then you will have to use libtraceparser.a to write your own util, or use traceprinter, sed, awk, grep, cut etc to generate a csv

Also, if it’s just a few events then if you select the two events in the tracelog view the timeline view will show the elapsed time between them

juliantcp · March 3, 2006, 9:05am

It works

Well, using traceprinter seems a bit easier (libtraceparser.a is complicate, I don’t see examples??).

A question: the output of the times gived by traceprinter is give in CPU clock cycles. It also gives a field of the header file, named “TRACE_CYCLES_PER_SEC”.

But I don’t see anywhere that TRACE_CYCLES_PER_SEC is the number of clock cycles per second.

It’s something like this:

TRACEPRINTER version 1.02 TRACEPARSER LIBRARY version 1.02 -- HEADER FILE INFORMATION -- TRACE_FILE_NAME:: /dev/shmem/logfile.kev TRACE_DATE:: Tue Feb 28 12:42:53 2006 TRACE_VER_MAJOR:: 1 TRACE_VER_MINOR:: 01 TRACE_LITTLE_ENDIAN:: TRUE TRACE_ENCODING:: 16 byte events TRACE_BOOT_DATE:: Tue Feb 28 10:12:09 2006 TRACE_CYCLES_PER_SEC:: 3007507500 TRACE_CPU_NUM:: 1 TRACE_SYSNAME:: QNX TRACE_NODENAME:: siva TRACE_SYS_RELEASE:: 6.3.0 TRACE_SYS_VERSION:: 2005/08/09-15:05:10EDT TRACE_MACHINE:: x86pc TRACE_SYSPAGE_LEN:: 0 -- KERNEL EVENTS -- t:0xcb94fe20 CPU:00 CONTROL :TIME msb:0x000018c9 lsb(offset):0xcb94f9e8 t:0x0000082b CPU:00 CONTROL :TIME msb:0x000018ca lsb(offset):0x00000510 t:0x015c2620 CPU:00 CONTROL :TIME msb:0x000018cb lsb(offset):0x015c2366 t:0x3fe3b4cb CPU:00 USREVENT:EVENT:0, d0:0x00000000 d1:0x00000000 t:0x3fe3c44a CPU:00 USREVENT:EVENT:0, d0:0x00000001 d1:0x00000000 t:0x3ff3cdcf CPU:00 USREVENT:EVENT:0, d0:0x00000000 d1:0x00000000 t:0x3ff3db14 CPU:00 USREVENT:EVENT:0, d0:0x00000001 d1:0x00000000 t:0x40227562 CPU:00 USREVENT:EVENT:0, d0:0x00000000 d1:0x00000000 t:0x40228336 CPU:00 USREVENT:EVENT:0, d0:0x00000001 d1:0x00000000

cburgess · March 3, 2006, 3:02pm

Yes, it’s the same value as the ClockCycles() clocks per second.