Folks, I''m using dtrace to try to get to the bottom of what appears to be a race condition. I am however quite uncomfortable with the ''timestamp'' output, finding that it seems to record the time of printing rather than the time of the event. ie. I get all the probes related to one CPU printed, then all the probes related to another CPU are printed, but I know there are dependencies which mean the output ought to be interleaved. I used timestamp to try to capture the time of the event, but the timestamps don''t seem to show the dependent events in the order they ought to occur, in fact the timestamps seem to relate more to time of output. Is there a way to timestamp or order output in the actual order of occurrance ?? TIA George
I am not an expert, but I believe that the timestamp variable is set at the time of the probe firing. There is an RFE open to get dtrace to do the merge itself to avoid this kind of confusion. On the other hand, since certain actions for certain probes do indeed take place when the dtrace buffer is downloaded by the dtrace executable, I wouldn''t be surprised if in certain circumstances it is possible to get the timestamp of the download instead of the probe firing. This may not work for your race condition, but I often take all but one CPU offline to avoid this problem. Of course, that only works when you are not dealing with production systems, and then if the race is not one that requires multiple CPUs. George Shepherd wrote:> Folks, > > I''m using dtrace to try to get to the bottom of what appears > to be a race condition. > > I am however quite uncomfortable with the ''timestamp'' output, finding > that it seems to record the time of printing rather than the time of > the event. > > ie. I get all the probes related to one CPU printed, then all the > probes related to another CPU are printed, but I know there are > dependencies which mean the output ought to be interleaved. > > I used timestamp to try to capture the time of the event, but > the timestamps don''t seem to show the dependent events in the order > they ought to occur, in fact the timestamps seem to relate more to > time of output. > > Is there a way to timestamp or order output in the actual order of > occurrance ?? > > TIA > George > > > _______________________________________________ > dtrace-discuss mailing list > dtrace-discuss at opensolaris.org-- blu "When Congress started Daylight Savings Time earlier, did they even consider what affect an extra hour of daylight would have on global warming? Well, did they?" ---------------------------------------------------------------------- Brian Utterback - Solaris RPE, Sun Microsystems, Inc. Ph:877-259-7345, Em:brian.utterback-at-ess-you-enn-dot-kom
Brendan Gregg - Sun Microsystems
2007-May-22 18:39 UTC
[dtrace-discuss] Dtrace: a timestamp question
G''Day George, On Tue, May 22, 2007 at 06:14:03PM +0100, George Shepherd wrote:> Folks, > > I''m using dtrace to try to get to the bottom of what appears > to be a race condition. > > I am however quite uncomfortable with the ''timestamp'' output, finding > that it seems to record the time of printing rather than the time of > the event. > > ie. I get all the probes related to one CPU printed, then all the > probes related to another CPU are printed, but I know there are > dependencies which mean the output ought to be interleaved. > > I used timestamp to try to capture the time of the event, but > the timestamps don''t seem to show the dependent events in the order > they ought to occur, in fact the timestamps seem to relate more to > time of output. > > Is there a way to timestamp or order output in the actual order of > occurrance ??The timestamp variable _does_ measure the occurance time; the shuffling of output is due to the way data is collected from the per-CPU buffers - which is performed asynchronously and at a default rate of 1 Hertz; this is great in terms of reducing performance overhead, but does mean you''ll need to post sort the output if that is important. Brendan -- Brendan [CA, USA]
> Date: Tue, 22 May 2007 11:39:21 -0700> From: brendan at sun.com> To: George.Shepherd at sun.com> Subject: Re: [dtrace-discuss] Dtrace: a timestamp question> CC: dtrace-discuss at opensolaris.org> > G''Day George,> > On Tue, May 22, 2007 at 06:14:03PM +0100, George Shepherd wrote:> > Folks,> > > > I''m using dtrace to try to get to the bottom of what appears > > to be a race condition.> > > > I am however quite uncomfortable with the ''timestamp'' output, finding > > that it seems to record the time of printing rather than the time of > > the event.> > > > ie. I get all the probes related to one CPU printed, then all the> > probes related to another CPU are printed, but I know there are> > dependencies which mean the output ought to be interleaved.> > > > I used timestamp to try to capture the time of the event, but > > the timestamps don''t seem to show the dependent events in the order > > they ought to occur, in fact the timestamps seem to relate more to> > time of output.> > > > Is there a way to timestamp or order output in the actual order of> > occurrance ??> > The timestamp variable _does_ measure the occurance time; the shuffling> of output is due to the way data is collected from the per-CPU buffers -> which is performed asynchronouslydoes asynchronous means "when ever a probe fires, probe & corresponding action is kept in queue data structure. and action were getting executing from that queue (or whatever DS)."? If that is the case then timestamp when probe is fired and timestamp when action is getting executed can be different depends how big queue is (or how many actions are pending to be executed.) in my case, in dtrace script there are 10 probes which are getting fired at 2 sec interval. Means I am collecting some statistics at every 10 sec''s interval. If I keep running my script for 10 sec''s, then time difference printed in BEGIN probe and END probe should be 2 * 10 = 20 sec''s (or very close to that). But time difference varies depends upon how complecated actions are and how big action queue is. Actually I have to match dtrace log output with different log files base upon time. In that both the log file will have different. Now I can not say when time message printed in my product log file, that is the output of dtrace. So I can not use dtrace output along with my product log file. Any idea how to resolve this. TIA Vineet and at a default rate of 1 Hertz;> this is great in terms of reducing performance overhead, but does> mean you''ll need to post sort the output if that is important.> > Brendan> > -- > Brendan> [CA, USA]> _______________________________________________> dtrace-discuss mailing list> dtrace-discuss at opensolaris.org _________________________________________________________________ Download Messenger. Start an i?m conversation. Support a cause. Join now. http://im.live.com/messenger/im/home/?source=TAGWL_MAY07 -------------- next part -------------- An HTML attachment was scrubbed... URL: <http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20070522/2daede71/attachment.html>
Brendan Gregg wrote: *> *>The timestamp variable _does_ measure the occurance time; the shuffling *>of output is due to the way data is collected from the per-CPU buffers - *>which is performed asynchronously and at a default rate of 1 Hertz; *>this is great in terms of reducing performance overhead, but does *>mean you''ll need to post sort the output if that is important. Hey Brendan.. Thanks for your reply..
Brendon.Gregg at Sun.com wrote: *> *>The timestamp variable _does_ measure the occurance time; the shuffling *>of output is due to the way data is collected from the per-CPU buffers - *>which is performed asynchronously and at a default rate of 1 Hertz; *>this is great in terms of reducing performance overhead, but does *>mean you''ll need to post sort the output if that is important. Hey Brendan, thanks for your reply.. I eventually found a maatching pollnotify() for my awakened thread but it was printed a long time before the trace of the thread going to sleep and being awakened. The timestamp was reasonable though.
George, Timestamps is one way to list the events in a particular order (needs sorting). The other option (not so elegant approach) would be disable all but one cpu. I agree that this is not useful (or good) in all cases. Thanks and regards, Sanjeev. George Shepherd wrote:> Brendon.Gregg at Sun.com wrote: > *> > *>The timestamp variable _does_ measure the occurance time; the shuffling > *>of output is due to the way data is collected from the per-CPU buffers - > *>which is performed asynchronously and at a default rate of 1 Hertz; > *>this is great in terms of reducing performance overhead, but does > *>mean you''ll need to post sort the output if that is important. > > Hey Brendan, > > thanks for your reply.. > > I eventually found a maatching pollnotify() for my awakened > thread but it was printed a long time before the trace of the > thread going to sleep and being awakened. > > The timestamp was reasonable though. > > _______________________________________________ > dtrace-discuss mailing list > dtrace-discuss at opensolaris.org >
Sanjeev Bagewadi wrote:> George, > > Timestamps is one way to list the events in a particular order (needs > sorting). > The other option (not so elegant approach) would be disable all but one > cpu. > I agree that this is not useful (or good) in all cases.esp. if a potential race condition is being analysed :-) -- Michael Schuster Sun Microsystems, Inc. recursion, n: see ''recursion''
michael schuster wrote:> Sanjeev Bagewadi wrote: >> George, >> >> Timestamps is one way to list the events in a particular order (needs >> sorting). >> The other option (not so elegant approach) would be disable all but >> one cpu. >> I agree that this is not useful (or good) in all cases. > > esp. if a potential race condition is being analysed :-) >Absolutely :-) -- Sanjeev.