Hi all,
I''m trying to understand a phenomenon here in my dtraced system
and associated with this I have a question on the pid provider.
I''m using a simple probe
pid$1::sge_add_event:entry
{
printf("\t%s(%d) tid %d", probefunc, arg1, tid);
}
to track a specific function call in a multi-threaded application
where more than a single thread issues this function.
My question is whether I can rely that these printf''s will appear in my
dtrace(1) output in the sequence of these
function calls or not?
Regards,
Andreas
Hi,
i think you cannot rely on that since different threads could be
executing in different CPUs calling that function and the output will be
collected when per CPU buffers are readed by dtrace(1) consumer.
I think the problem it''s similar to this one:
http://www.opensolaris.org/jive/thread.jspa?messageID=25834擪
HTH,
Gonzalo.
Andreas.Haas at Sun.COM wrote On 10/19/06 01:42 PM,:
> Hi all,
>
> I''m trying to understand a phenomenon here in my dtraced system
> and associated with this I have a question on the pid provider.
>
> I''m using a simple probe
>
> pid$1::sge_add_event:entry
> {
> printf("\t%s(%d) tid %d", probefunc, arg1, tid);
> }
>
> to track a specific function call in a multi-threaded application
> where more than a single thread issues this function.
>
> My question is whether I can rely that these printf''s will appear
in
> my dtrace(1) output in the sequence of these
> function calls or not?
>
> Regards,
> Andreas
>
> _______________________________________________
> dtrace-discuss mailing list
> dtrace-discuss at opensolaris.org
On Thu, 19 Oct 2006, Gonzalo Siero Humet wrote:> > Hi, > > i think you cannot rely on that since different threads could be executing > in different CPUs calling that function and the output will be collected when > per CPU buffers are readed by dtrace(1) consumer.I see. Now assumed I would add ''timestamp'' to my the printf()''s pid$1::sge_add_event:entry { printf("\t%d: %s(%d) tid %d", timestamp, probefunc, arg1, tid); } and then post-process that output using sort(1) based on these time stamps when the dtrace output is generated. Could I then trust the sequence or are timestamps determined at the time when CPU buffers are read by dtrace(1) consumer? Thanks, Andreas
Andreas.Haas at Sun.COM wrote:> Now assumed I would add ''timestamp'' to my the printf()''s > > pid$1::sge_add_event:entry > { > printf("\t%d: %s(%d) tid %d", timestamp, probefunc, arg1, tid); > } > > and then post-process that output using sort(1) based on these time stamps > when the dtrace output is generated. > > Could I then trust the sequence or are timestamps determined at the time > when CPU buffers are read by dtrace(1) consumer?Andreas:> uint64_t timestamp The current value of a nanosecond timestamp > counter. This counter increments from an > arbitrary point in the past and should only be > used for relative computations.the phrase "used for relative computations" implies (to me) that timestamp is meant for what you''re trying to do. HTH -- Michael Schuster +49 89 46008-2974 / x62974 visit the online support center: http://www.sun.com/osc/ Recursion, n.: see ''Recursion''
On Thu, 19 Oct 2006, Michael Schuster wrote:> Andreas.Haas at Sun.COM wrote: > >> Now assumed I would add ''timestamp'' to my the printf()''s >> >> pid$1::sge_add_event:entry >> { >> printf("\t%d: %s(%d) tid %d", timestamp, probefunc, arg1, tid); >> } >> >> and then post-process that output using sort(1) based on these time stamps >> when the dtrace output is generated. >> >> Could I then trust the sequence or are timestamps determined at the time >> when CPU buffers are read by dtrace(1) consumer? > > Andreas: > >> uint64_t timestamp The current value of a nanosecond timestamp >> counter. This counter increments from an >> arbitrary point in the past and should only be >> used for relative computations. > > the phrase "used for relative computations" implies (to me) that timestamp is > meant for what you''re trying to do.Thanks, Michael. I tried and it works :-) Btw. I was surprised even to see timestamps were unique with the test runs I performed. Regards, Andreas
Andreas.Haas at Sun.COM wrote:> Thanks, Michael. I tried and it works :-)good to know :-)> Btw. I was surprised even to see timestamps were unique with the test > runs I performed.why? -- Michael Schuster +49 89 46008-2974 / x62974 visit the online support center: http://www.sun.com/osc/ Recursion, n.: see ''Recursion''
Andreas, Since the trace records going into the buffer have to be fixed length, the "formatting" of trace data is done by the consumer. For example, a printf can have a format string that generates variable length output. However, the actual data values specified by trace or printf are generated by the kernel DIF programs at the time the probe fires, so timestamp will have the value you want. Chip Michael Schuster wrote:> Andreas.Haas at Sun.COM wrote: > >> Now assumed I would add ''timestamp'' to my the printf()''s >> >> pid$1::sge_add_event:entry >> { >> printf("\t%d: %s(%d) tid %d", timestamp, probefunc, arg1, tid); >> } >> >> and then post-process that output using sort(1) based on these time >> stamps >> when the dtrace output is generated. >> >> Could I then trust the sequence or are timestamps determined at the time >> when CPU buffers are read by dtrace(1) consumer? > > Andreas: > >> uint64_t timestamp The current value of a nanosecond timestamp >> counter. This counter increments from an >> arbitrary point in the past and should only be >> used for relative computations. > > the phrase "used for relative computations" implies (to me) that > timestamp is meant for what you''re trying to do. > > HTH
On Thu, 19 Oct 2006, Michael Schuster wrote:> Andreas.Haas at Sun.COM wrote: > >> Thanks, Michael. I tried and it works :-) > > good to know :-) > >> Btw. I was surprised even to see timestamps were unique with the test runs >> I performed. > > why?Well, I simply didn''t expect them to be unique for a multi-threaded app on a 4 CPU machine. Although I understand I can''t really rely on their uniqueness, yet until now I was always lucky. Cheers, Andreas Sun Microsystems GmbH | ++49 +941 3075-131 Dr.-Leo-Ritter-Str. 7 | N1 Grid Engine D-93049 Regensburg/Germany | System Engineering Group Lead
Andreas.Haas at Sun.COM wrote:> On Thu, 19 Oct 2006, Michael Schuster wrote: > >> Andreas.Haas at Sun.COM wrote: >> >>> Thanks, Michael. I tried and it works :-) >> >> good to know :-) >> >>> Btw. I was surprised even to see timestamps were unique with the >>> test runs I performed. >> >> why? > > Well, I simply didn''t expect them to be unique for a multi-threaded > app on a 4 CPU machine. Although I understand I can''t really rely on > their uniqueness, yet until now I was always lucky.You could add the "cpu" builtin variable to your sort key, on the off chance two timestamp values end up being the same. On the other hand, if the timestamp values are the same, does the order matter. ;-) Chip