TraceEvent _NTO_TRACE_INSERTUSRSTREVENT not working

QNX Newsgroups (Archives) qnx.ddk
1

We are having some trouble with using QNX6 (6.2.1) and the instrumented
kernel with the TraceEvent function and I am hoping someone can shed some
light on what we are doing wrong.



A resource manager that we have written has had several TraceEvents added to
it like so:



static char errstr[BHN_DEBUG_BUFF_SIZE];

inline void XYZ_Trace1(int event, char *format, unsigned long arg1 ){

sprintf(errstr , format, arg1 );

TraceEvent(_NTO_TRACE_INSERTUSRSTREVENT, event, errstr );

}



I rebuilt the osimage with the instrumented kernel setup and run
“tracelogger -d” then my program to enable my TraceEvents then
“traceprinter” to decode the event log.



The problem is that none of my events ever show up in the events dumped out.
Is there something that we are missing?



Below is the program used to enable the tracing:



#include <sys/trace.h>

#include <errno.h>

int main(int argc, char **argv)

{

/* set wide emitting mode */

if( TraceEvent(_NTO_TRACE_SETALLCLASSESWIDE) == -1 )

printf( “Error1\n” );



/* include all classes */

if( TraceEvent(_NTO_TRACE_ADDALLCLASSES)== -1 )

printf( “Error2\n” );



/* start tracing */

if( TraceEvent(_NTO_TRACE_START)== -1)

printf( “Error3 errno=%d\n”, errno );



return (0);

}



Sincerely

Allan

2

I have not used trace events in QNX 6. I have used them in QNX4.

Did you check the severity level of events being logged and the severity
level of events being displayed?

“Allan Smith” <aes@connecttech.com> wrote in message
news:d367s9$lmk$1@inn.qnx.com…

We are having some trouble with using QNX6 (6.2.1) and the instrumented
kernel with the TraceEvent function and I am hoping someone can shed some
light on what we are doing wrong.



A resource manager that we have written has had several TraceEvents added
to
it like so:



static char errstr[BHN_DEBUG_BUFF_SIZE];

inline void XYZ_Trace1(int event, char *format, unsigned long arg1 ){

sprintf(errstr , format, arg1 );

TraceEvent(_NTO_TRACE_INSERTUSRSTREVENT, event, errstr );

}



I rebuilt the osimage with the instrumented kernel setup and run
“tracelogger -d” then my program to enable my TraceEvents then
“traceprinter” to decode the event log.



The problem is that none of my events ever show up in the events dumped
out.
Is there something that we are missing?



Below is the program used to enable the tracing:



#include <sys/trace.h

#include <errno.h

int main(int argc, char **argv)

{

/* set wide emitting mode */

if( TraceEvent(_NTO_TRACE_SETALLCLASSESWIDE) == -1 )

printf( “Error1\n” );



/* include all classes */

if( TraceEvent(_NTO_TRACE_ADDALLCLASSES)== -1 )

printf( “Error2\n” );



/* start tracing */

if( TraceEvent(_NTO_TRACE_START)== -1)

printf( “Error3 errno=%d\n”, errno );



return (0);

}



Sincerely

Allan
\

3

Well TraceEvents under QNX6 seem to be quite different than the way QNX4.
There isn’t a severity filter but a very complex set of filters you can
apply. Under QNX4 if my memory serves me correctly you control the severity
of level via tracectrl or some function like that. Under QNX6 it is done
via TraceEvent calls in a program you have to write yourself.

I have a feeling that there is a special “class” that I have to enable to
get these events to show up but everything I have tried has not worked.

“Bill Caroselli” <qtps@earthlink.net> wrote in message
news:d36mvc$324$2@inn.qnx.com…

I have not used trace events in QNX 6. I have used them in QNX4.

Did you check the severity level of events being logged and the severity
level of events being displayed?

“Allan Smith” <> aes@connecttech.com> > wrote in message
news:d367s9$lmk$> 1@inn.qnx.com> …
We are having some trouble with using QNX6 (6.2.1) and the instrumented
kernel with the TraceEvent function and I am hoping someone can shed some
light on what we are doing wrong.

4

Hi Allan

What events ARE showing up?

I would temporarilly make my events have those same properties and see if
they show up. If they don’t, then your doing something wrong in the
program. If the do, then there is a filter issue somewhere that you have to
find.

Good luck

“Allan Smith” <aes@connecttech.com> wrote in message
news:d36nr6$3nc$1@inn.qnx.com…

Well TraceEvents under QNX6 seem to be quite different than the way QNX4.
There isn’t a severity filter but a very complex set of filters you can
apply. Under QNX4 if my memory serves me correctly you control the
severity
of level via tracectrl or some function like that. Under QNX6 it is done
via TraceEvent calls in a program you have to write yourself.

I have a feeling that there is a special “class” that I have to enable to
get these events to show up but everything I have tried has not worked.

5

Allan Smith <aes@connecttech.com> wrote:

We are having some trouble with using QNX6 (6.2.1) and the instrumented
kernel with the TraceEvent function and I am hoping someone can shed some
light on what we are doing wrong.



A resource manager that we have written has had several TraceEvents added to
it like so:



static char errstr[BHN_DEBUG_BUFF_SIZE];

inline void XYZ_Trace1(int event, char *format, unsigned long arg1 ){

sprintf(errstr , format, arg1 );

TraceEvent(_NTO_TRACE_INSERTUSRSTREVENT, event, errstr );

}

What value do you pass for event? It should be in the range
_NTO_TRACE_USERFIRST to _NTO_TRACE_USERLAST.

-David

David Gibbs
QNX Training Services
dagibbs@qnx.com

6

Thanks for the suggestion. In my tests the values for event have been a
value between 0 to 12. From what I see in trace.h the range can be from 0
to 0x3ff.

My gut feeling is there is a special TraceEvent call that I must make to
enable USER events.

Allan


“David Gibbs” <dagibbs@qnx.com> wrote in message
news:d3e6th$fac$1@inn.qnx.com…

What value do you pass for event? It should be in the range
_NTO_TRACE_USERFIRST to _NTO_TRACE_USERLAST.

7

Allan Smith <aes@connecttech.com> wrote:

Thanks for the suggestion. In my tests the values for event have been a
value between 0 to 12. From what I see in trace.h the range can be from 0
to 0x3ff.

My gut feeling is there is a special TraceEvent call that I must make to
enable USER events.

Have you tried running a little test program that just issues one of
those user events (with none of the setup code) every 10 milliseconds
or so, then use either tracelogger, or the IDE, to grab say 3 seconds
of trace data and look for user events?

e.g.
tracelogger -f tracedata.kev -s3

Have you checked the return value of the TraceEvent() calls that
you are issuing?

-David

David Gibbs
QNX Training Services
dagibbs@qnx.com

8

I had checked the return values of the TraceEvent calls that enable the
filters etc, but had not checked the TraceEvent calls in my code that I am
trying to trace.

Low and behold I am getting a return value of -1 and errno of 89 (ENOSYS).
Do you have any idea what can cause this error with TraceEvents?

Al

“David Gibbs” <dagibbs@qnx.com> wrote in message
news:d3eho3$n64$1@inn.qnx.com…

Have you checked the return value of the TraceEvent() calls that
you are issuing?

9

Allan Smith <aes@connecttech.com> wrote:

I had checked the return values of the TraceEvent calls that enable the
filters etc, but had not checked the TraceEvent calls in my code that I am
trying to trace.

Low and behold I am getting a return value of -1 and errno of 89 (ENOSYS).
Do you have any idea what can cause this error with TraceEvents?

I don’t know. With non-instrumented kernel, it would be 84 (EOPNOSUP),
but don’t know what would cause an ENOSYS.

Can you post a small test program that demonstrates this which I could
try?

What version of QNX are you working with?

-David

David Gibbs
QNX Training Services
dagibbs@qnx.com

10

I am working with QNX 6.2.1a

The actual spot I am trying to use TraceEvent in, is a resource manager
based in part on the devc-ser8250 sample source code.

I made a simple test program to use TraceEvent the way I am trying to use it
shown below. Strange thing is it is not showning any errors, but I am still
not seeing any of these event messages in the trace log either.

I run the instrumented kernel.
I then run “tracelogger -d &”
Then I run “bhntraceon” to enable my events (source below)
I then run “test” (source below)
Then I run “traceprinter >tmp.txt”
and look through the output in tmp.txt and no sign of the “Test” string is
in the output.

test.c is as follows:
#include <sys/trace.h>
#include <errno.h>

main( int argc, char **argv ){
int retval;

while( 1 ){
retval = TraceEvent( _NTO_TRACE_INSERTUSRSTREVENT, 12, “Test” );
if( retval == -1 )
printf( “TraceEvent errno=%d\n”, errno );
sleep( 10 );
}
}

bhntraceon shown below:
#include <sys/trace.h>
#include <errno.h>

int main(int argc, char *argv)
{
/ set fast emitting mode */
if( TraceEvent(_NTO_TRACE_SETALLCLASSESWIDE) == -1 )
printf( “Error1\n” );

/* include all classes /
if( TraceEvent(_NTO_TRACE_ADDALLCLASSES)== -1 )
printf( “Error2\n” );


/ start tracing */
if( TraceEvent(_NTO_TRACE_START)== -1)
printf( “Error3 errno=%d\n”, errno );

return (0);
}

“David Gibbs” <dagibbs@qnx.com> wrote in message
news:d3gqlg$eiq$1@inn.qnx.com…

Allan Smith <> aes@connecttech.com> > wrote:
I had checked the return values of the TraceEvent calls that enable the
filters etc, but had not checked the TraceEvent calls in my code that I
am
trying to trace.

Low and behold I am getting a return value of -1 and errno of 89
(ENOSYS).
Do you have any idea what can cause this error with TraceEvents?

I don’t know. With non-instrumented kernel, it would be 84 (EOPNOSUP),
but don’t know what would cause an ENOSYS.

Can you post a small test program that demonstrates this which I could
try?

What version of QNX are you working with?

-David

David Gibbs
QNX Training Services
dagibbs@qnx.com

11

Allan Smith <aes@connecttech.com> wrote:

I am working with QNX 6.2.1a

Ok, I don’t have a 6.2.1A around, so tried it with a 6.3.0 box. There’s
a couple things.

I made a simple test program to use TraceEvent the way I am trying to use it
shown below. Strange thing is it is not showning any errors, but I am still
not seeing any of these event messages in the trace log either.

I run the instrumented kernel.
I then run “tracelogger -d &”
Then I run “bhntraceon” to enable my events (source below)
I then run “test” (source below)

Note: test is a dangerous name for a test progam. See, if you’re doing
it from the command line, and you try to run it by typing “test”, you won’t
run your program, you’ll run the shell builtin “test”.

Also, looking at the code, you issue on of these every 10 seconds – that’s
not very often, compared to the amount of data you might be collecting. Try
issuing the event every delay(100) (1/10 second) or so.


Then I run “traceprinter >tmp.txt”
and look through the output in tmp.txt and no sign of the “Test” string is
in the output.

Nope, traceprinter doesn’t turn it into a string. It doesn’t know much
about user events (and, actually, string & data user events are, to it,
just interchangeable user events.)

Try searching for the string “USREVENT” in the log.

I get much of like the following in my log:

t:0x3ec39c9b CPU:00 USREVENT:EVENT:12, d0:0x74736554 d1:0x00000000
t:0x40f9cb95 CPU:00 USREVENT:EVENT:12, d0:0x74736554 d1:0x00000000
t:0x4331fe01 CPU:00 USREVENT:EVENT:12, d0:0x74736554 d1:0x00000000
t:0x459b975d CPU:00 USREVENT:EVENT:12, d0:0x74736554 d1:0x00000000
t:0x47d6aa16 CPU:00 USREVENT:EVENT:12, d0:0x74736554 d1:0x00000000
t:0x4a10ed0a CPU:00 USREVENT:EVENT:12, d0:0x74736554 d1:0x00000000
t:0x4c832b26 CPU:00 USREVENT:EVENT:12, d0:0x74736554 d1:0x00000000
t:0x4eea275e CPU:00 USREVENT:EVENT:12, d0:0x74736554 d1:0x00000000
t:0x512029bb CPU:00 USREVENT:EVENT:12, d0:0x74736554 d1:0x00000000
t:0x5374ccf3 CPU:00 USREVENT:EVENT:12, d0:0x74736554 d1:0x00000000

Note that 0x74736554 is the ascii characters ‘t’ ‘s’ ‘e’ ‘T’. This
is x86, so it is litte-endian, of course.

-David

David Gibbs
QNX Training Services
dagibbs@qnx.com

12

Thanks for the tips David.

When I run programs in a local directory I always run them with a ./ prefix
so my “test” program did get run, but thanks for the warning.

I had searched the traceprinter log for :12 in case the events were not
coming out as expected as well and none of these events were in the log.

I did not know that traceprinter would not decode the ascii strings. I
guess I would have to write my own app to do this then?

I was trying to use TraceEvent to give me some flow through my code along
with possible errors that it might have come across. It looked like a good
way to provide this without a lot of overhead. We have done this under
QNX4, but QNX6’s event logging seems very different and cumbersome to use in
this way.

Perhaps there is a better way?

Thank you again for your input.

Allan
“David Gibbs” <dagibbs@qnx.com> wrote in message
news:d3jme1$j2m$1@inn.qnx.com…

Allan Smith <> aes@connecttech.com> > wrote:
I am working with QNX 6.2.1a

Ok, I don’t have a 6.2.1A around, so tried it with a 6.3.0 box. There’s
a couple things.

I made a simple test program to use TraceEvent the way I am trying to use
it
shown below. Strange thing is it is not showning any errors, but I am
still
not seeing any of these event messages in the trace log either.

I run the instrumented kernel.
I then run “tracelogger -d &”
Then I run “bhntraceon” to enable my events (source below)
I then run “test” (source below)

Note: test is a dangerous name for a test progam. See, if you’re doing
it from the command line, and you try to run it by typing “test”, you
won’t
run your program, you’ll run the shell builtin “test”.

Also, looking at the code, you issue on of these every 10 seconds –
that’s
not very often, compared to the amount of data you might be collecting.
Try
issuing the event every delay(100) (1/10 second) or so.


Then I run “traceprinter >tmp.txt”
and look through the output in tmp.txt and no sign of the “Test” string
is
in the output.

Nope, traceprinter doesn’t turn it into a string. It doesn’t know much
about user events (and, actually, string & data user events are, to it,
just interchangeable user events.)

Try searching for the string “USREVENT” in the log.

I get much of like the following in my log:

t:0x3ec39c9b CPU:00 USREVENT:EVENT:12, d0:0x74736554 d1:0x00000000
t:0x40f9cb95 CPU:00 USREVENT:EVENT:12, d0:0x74736554 d1:0x00000000
t:0x4331fe01 CPU:00 USREVENT:EVENT:12, d0:0x74736554 d1:0x00000000
t:0x459b975d CPU:00 USREVENT:EVENT:12, d0:0x74736554 d1:0x00000000
t:0x47d6aa16 CPU:00 USREVENT:EVENT:12, d0:0x74736554 d1:0x00000000
t:0x4a10ed0a CPU:00 USREVENT:EVENT:12, d0:0x74736554 d1:0x00000000
t:0x4c832b26 CPU:00 USREVENT:EVENT:12, d0:0x74736554 d1:0x00000000
t:0x4eea275e CPU:00 USREVENT:EVENT:12, d0:0x74736554 d1:0x00000000
t:0x512029bb CPU:00 USREVENT:EVENT:12, d0:0x74736554 d1:0x00000000
t:0x5374ccf3 CPU:00 USREVENT:EVENT:12, d0:0x74736554 d1:0x00000000

Note that 0x74736554 is the ascii characters ‘t’ ‘s’ ‘e’ ‘T’. This
is x86, so it is litte-endian, of course.

-David

David Gibbs
QNX Training Services
dagibbs@qnx.com

13

Allan Smith <aes@connecttech.com> wrote:

Thanks for the tips David.

I had searched the traceprinter log for :12 in case the events were not
coming out as expected as well and none of these events were in the log.

I did not know that traceprinter would not decode the ascii strings. I
guess I would have to write my own app to do this then?

Yes, you’d have to use the traceparser() library routines to do so.

I was trying to use TraceEvent to give me some flow through my code along
with possible errors that it might have come across. It looked like a good
way to provide this without a lot of overhead. We have done this under
QNX4, but QNX6’s event logging seems very different and cumbersome to use in
this way.

I do use it this way, actually. I generally use simple events, not string
events, and use one of the two integers for the line number, and the other
for a source module/executable identifier. It generally works reasonably
well, though nowadays, I generally use the System Analysis/System Profiling
Perspective of the IDE for analyzing my .kev files.

Perhaps there is a better way?

slogger would be my other choice – it doesn’t require root, or the
instrumented kernel, but does require slogger.

-David

David Gibbs
QNX Training Services
dagibbs@qnx.com

14

Allan Smith wrote:

Thanks for the tips David.

When I run programs in a local directory I always run them with a ./ prefix
so my “test” program did get run, but thanks for the warning.

I had searched the traceprinter log for :12 in case the events were not
coming out as expected as well and none of these events were in the log.

I did not know that traceprinter would not decode the ascii strings. I
guess I would have to write my own app to do this then?

It will decode them if there are no non-printable characters in the
string. It’s a little simplistic though, and considers ‘\n’ non
printable. :v)

I was trying to use TraceEvent to give me some flow through my code along
with possible errors that it might have come across. It looked like a good
way to provide this without a lot of overhead. We have done this under
QNX4, but QNX6’s event logging seems very different and cumbersome to use in
this way.

Perhaps there is a better way?

Thank you again for your input.

Allan
“David Gibbs” <> dagibbs@qnx.com> > wrote in message
news:d3jme1$j2m$> 1@inn.qnx.com> …

Allan Smith <> aes@connecttech.com> > wrote:

I am working with QNX 6.2.1a

Ok, I don’t have a 6.2.1A around, so tried it with a 6.3.0 box. There’s
a couple things.


I made a simple test program to use TraceEvent the way I am trying to use
it
shown below. Strange thing is it is not showning any errors, but I am
still
not seeing any of these event messages in the trace log either.

I run the instrumented kernel.
I then run “tracelogger -d &”
Then I run “bhntraceon” to enable my events (source below)
I then run “test” (source below)

Note: test is a dangerous name for a test progam. See, if you’re doing
it from the command line, and you try to run it by typing “test”, you
won’t
run your program, you’ll run the shell builtin “test”.

Also, looking at the code, you issue on of these every 10 seconds –
that’s
not very often, compared to the amount of data you might be collecting.
Try
issuing the event every delay(100) (1/10 second) or so.



Then I run “traceprinter >tmp.txt”
and look through the output in tmp.txt and no sign of the “Test” string
is
in the output.

Nope, traceprinter doesn’t turn it into a string. It doesn’t know much
about user events (and, actually, string & data user events are, to it,
just interchangeable user events.)

Try searching for the string “USREVENT” in the log.

I get much of like the following in my log:

t:0x3ec39c9b CPU:00 USREVENT:EVENT:12, d0:0x74736554 d1:0x00000000
t:0x40f9cb95 CPU:00 USREVENT:EVENT:12, d0:0x74736554 d1:0x00000000
t:0x4331fe01 CPU:00 USREVENT:EVENT:12, d0:0x74736554 d1:0x00000000
t:0x459b975d CPU:00 USREVENT:EVENT:12, d0:0x74736554 d1:0x00000000
t:0x47d6aa16 CPU:00 USREVENT:EVENT:12, d0:0x74736554 d1:0x00000000
t:0x4a10ed0a CPU:00 USREVENT:EVENT:12, d0:0x74736554 d1:0x00000000
t:0x4c832b26 CPU:00 USREVENT:EVENT:12, d0:0x74736554 d1:0x00000000
t:0x4eea275e CPU:00 USREVENT:EVENT:12, d0:0x74736554 d1:0x00000000
t:0x512029bb CPU:00 USREVENT:EVENT:12, d0:0x74736554 d1:0x00000000
t:0x5374ccf3 CPU:00 USREVENT:EVENT:12, d0:0x74736554 d1:0x00000000

Note that 0x74736554 is the ascii characters ‘t’ ‘s’ ‘e’ ‘T’. This
is x86, so it is litte-endian, of course.

-David

David Gibbs
QNX Training Services
dagibbs@qnx.com
\

–
cburgess@qnx.com

15

Thank you for your feedback.

How much overhead will slog* functions put on a system when the user does
not enable our specific information in their slogger output?

IE we would like to put in trace info into a production resource manager
that can be turned on when needed but not bog down the driver with all the
slog* calls if they are not being currently used.


“David Gibbs” <dagibbs@qnx.com> wrote in message
news:d3k3v2$s4g$2@inn.qnx.com…

slogger would be my other choice – it doesn’t require root, or the
instrumented kernel, but does require slogger.

16

Allan Smith <aes@connecttech.com> wrote:

Thank you for your feedback.

How much overhead will slog* functions put on a system when the user does
not enable our specific information in their slogger output?

IE we would like to put in trace info into a production resource manager
that can be turned on when needed but not bog down the driver with all the
slog* calls if they are not being currently used.

Using the TraceEvent() stuff will always require the instrumented
kernel, you can’t really switch instrumented/not on the fly, though.
Instrumented kernel, when not runs at better than 97% of regular
kernel speed.

The slog*() functions are, basically, a MsgSend() to the slogger
daemon. It would, of course, be cheapest to turn them on/off in the
server, maybe based on a command line option (at least), and if you
want to dynamically do this without restarting the resource manager,
possibly a devctl() or custom message to enable/disable the logging
at the issuer side. Then, when off, it’s just a test and branch.

I haven’t looked in detail at slogger configurability, but I’m pretty
sure it only limits based on severity – not based on originator or
anything like that. Assuming you set the severity to be logged below
what you’re issuing, it will be a Send/Receive/Reply to slogger, which
will do a test, find severity to not be logged, and do nothing further
with the request. But, it will still be a S/R/R, meaning it is
cheaper to turn things off on the issuer side, rather than on the
slogger side.

Hope this helps clarify the decision.

-David

David Gibbs
QNX Training Services
dagibbs@qnx.com

17

Thanks for the information. This does help a lot. I think going with a
command line switch to turn on slog output is the way to go.

I have one more question. I see there are OEM codes that can be defined
like _SLOGC_TEST, _SLOGC_3COM etc. Do you know how we would go about
getting an _SLOGC_CTI added?


“David Gibbs” <dagibbs@qnx.com> wrote in message
news:d4tmko$qb3$1@inn.qnx.com…

Using the TraceEvent() stuff will always require the instrumented
kernel, you can’t really switch instrumented/not on the fly, though.
Instrumented kernel, when not runs at better than 97% of regular
kernel speed.

The slog*() functions are, basically, a MsgSend() to the slogger
daemon. It would, of course, be cheapest to turn them on/off in the
server, maybe based on a command line option (at least), and if you
want to dynamically do this without restarting the resource manager,
possibly a devctl() or custom message to enable/disable the logging
at the issuer side. Then, when off, it’s just a test and branch.

I haven’t looked in detail at slogger configurability, but I’m pretty
sure it only limits based on severity – not based on originator or
anything like that. Assuming you set the severity to be logged below
what you’re issuing, it will be a Send/Receive/Reply to slogger, which
will do a test, find severity to not be logged, and do nothing further
with the request. But, it will still be a S/R/R, meaning it is
cheaper to turn things off on the issuer side, rather than on the
slogger side.

Hope this helps clarify the decision.

-David

David Gibbs
QNX Training Services
dagibbs@qnx.com

18

Allan Smith <aes@connecttech.com> wrote:

Thanks for the information. This does help a lot. I think going with a
command line switch to turn on slog output is the way to go.

I have one more question. I see there are OEM codes that can be defined
like _SLOGC_TEST, _SLOGC_3COM etc. Do you know how we would go about
getting an _SLOGC_CTI added?

I don’t know on that one. At a guess, I’d bet it would be
“contact your technical support rep”. At least, that’s what
we used to do for Trace codes in QNX4 back when I was in
tech support. (Lo those many moons ago.)

-David

David Gibbs
QNX Training Services
dagibbs@qnx.com