Guys,
I''m trying to write a script that (among other things) calculates how
much time was spent executing each process. Now, my understanding is
that the following is ALWAYS true:
walltimestamp >= (curpsinfo->pr_start.tv_sec*1000000000 +
curpsinfo->pr_start.tv_nsec);
for one simple reason only -- process start time was in the PAST!
Well, the following script seems to disagree:
$ cat tt.d
#!/usr/sbin/dtrace -s
#pragma D option quiet
proc:::exit
{
printf("The process (%s) dies %d nanoseconds old\n", execname,
(walltimestamp - curpsinfo->pr_start.tv_sec*1000000000 -
curpsinfo->pr_start.tv_nsec));
}
$ ./tt.d &
[1] 9848
$ ls > /dev/null
$ The process (ls) dies -11653778 nanoseconds old
Thoughts?
Thanks,
Roman.
P.S. What is even more weird is that the following seems to work:
$ ./tt.d -c ls
The process (ls) dies 277239688 nanoseconds old
On Thu, 2007-12-20 at 06:26 -0800, michael schuster wrote:> what I did notice though is that walltimestamp does NOT increase at the same rate > as timestamp does,Given the documentation I would consider this to be a bug. And a pretty nasty one at that. I think if the consensus is that it is, indeed a bug, the least we can do is to put a note on our Wiki. Would anybody from team DTrace care to comment?> ie much less frequently (search for a thread started by > me in the last few months ;-). I don''t know whether that helps in your caseDo you mean this thread? http://marc.info/?l=opensolaris-dtrace-discuss&m=119101596422651&w=2 The reply you got there wasn''t actually an answer to the "what is walltimestamp?" question ;-) Thanks, Roman.
Roman Shaposhnik wrote:> On Thu, 2007-12-20 at 06:26 -0800, michael schuster wrote: >> what I did notice though is that walltimestamp does NOT increase at the same rate >> as timestamp does, > > Given the documentation I would consider this to be a bug. And a > pretty nasty one at that. I think if the consensus is that it is, indeed > a bug, the least we can do is to put a note on our Wiki.I''d agree with "this is a doc. bug".> Would anybody from team DTrace care to comment? > >> ie much less frequently (search for a thread started by >> me in the last few months ;-). I don''t know whether that helps in your case > > Do you mean this thread? > http://marc.info/?l=opensolaris-dtrace-discuss&m=119101596422651&w=2 > > The reply you got there wasn''t actually an answer to the "what is walltimestamp?" > question ;-)yes it is, and Brian Utterback did answer my question at the time (not that I was really happy about it, but that''s a different story). Michael -- Michael Schuster Sun Microsystems, Inc. recursion, n: see ''recursion''
On Thu, Dec 20, 2007 at 12:38:26PM -0800, Roman Shaposhnik wrote:> On Thu, 2007-12-20 at 06:26 -0800, michael schuster wrote: > > what I did notice though is that walltimestamp does NOT increase at the same rate > > as timestamp does, > > Given the documentation I would consider this to be a bug. And a > pretty nasty one at that. I think if the consensus is that it is, indeed > a bug, the least we can do is to put a note on our Wiki. > > Would anybody from team DTrace care to comment?This is not a bug at all -- this is the difference between gethrtime(3C) and gettimeofday(3C). (If you write a program that does gethrtime() and gettimeofday() for extended periods of time, you should see the same degree of divergence as the D program. If you don''t, then that is a bug.) In terms of the difference here, I think the documentation is actually reasonably clear on this; from http://wikis.sun.com/display/DTrace/Variables: 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. walltimestamp The current number of nanoseconds since 00:00 Universal Coordinated Time, January 1, 1970. But if you''d like, we can add a note to walltimestamp that -- as a consequence of being UTC -- it can have all sorts of strange things happen to it (e.g. leap seconds, backwards adjustments, etc.). Or better, you could add such a note. ;) - Bryan -------------------------------------------------------------------------- Bryan Cantrill, Sun Microsystems FishWorks. http://blogs.sun.com/bmc
Bryan Cantrill wrote:> On Thu, Dec 20, 2007 at 12:38:26PM -0800, Roman Shaposhnik wrote: >> On Thu, 2007-12-20 at 06:26 -0800, michael schuster wrote: >>> what I did notice though is that walltimestamp does NOT increase at the same rate >>> as timestamp does, >> Given the documentation I would consider this to be a bug. And a >> pretty nasty one at that. I think if the consensus is that it is, indeed >> a bug, the least we can do is to put a note on our Wiki. >> >> Would anybody from team DTrace care to comment? > > This is not a bug at all -- this is the difference between gethrtime(3C) > and gettimeofday(3C). (If you write a program that does gethrtime() and > gettimeofday() for extended periods of time, you should see the same > degree of divergence as the D program. If you don''t, then that is a bug.) > In terms of the difference here, I think the documentation is actually > reasonably clear on this; from http://wikis.sun.com/display/DTrace/Variables: > > 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. > > walltimestamp The current number of nanoseconds since 00:00 Universal > Coordinated Time, January 1, 1970.I think after reading this, a reasonable expectation would be that these two increment "in lockstep" most of the time (as I had when I started the other thread we mentioned previously). The they don''t is a documentation bug, IMO. Michael -- Michael Schuster Sun Microsystems, Inc. recursion, n: see ''recursion''
> >> Given the documentation I would consider this to be a bug. And a > >> pretty nasty one at that. I think if the consensus is that it is, indeed > >> a bug, the least we can do is to put a note on our Wiki. > >> > >> Would anybody from team DTrace care to comment? > > > > This is not a bug at all -- this is the difference between gethrtime(3C) > > and gettimeofday(3C). (If you write a program that does gethrtime() and > > gettimeofday() for extended periods of time, you should see the same > > degree of divergence as the D program. If you don''t, then that is a bug.) > > In terms of the difference here, I think the documentation is actually > > reasonably clear on this; from http://wikis.sun.com/display/DTrace/Variables: > > > > 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. > > > > walltimestamp The current number of nanoseconds since 00:00 Universal > > Coordinated Time, January 1, 1970. > > I think after reading this, a reasonable expectation would be that these > two increment "in lockstep" most of the timeI disagree; I don''t think that is a resonable expectation -- it''s certainly not supported by the documentation anyway. (If anything the warning next to timestamp should dissuade such expectations.) But my opinion may be biased by the fact that I already understand the difference between monotonic and walltime; it''s hard for me to see through this through the eyes of someone who has never before thought about time. So if we need an additional sentence or two to clarify, I would encourage you to add them... - Bryan -------------------------------------------------------------------------- Bryan Cantrill, Sun Microsystems FishWorks. http://blogs.sun.com/bmc
On Dec 20, 2007 3:28 PM, Bryan Cantrill <bmc at eng.sun.com> wrote:> timestamp should dissuade such expectations.) But my opinion may be > biased by the fact that I already understand the difference between > monotonic and walltime; it''s hard for me to see through this through the > eyes of someone who has never before thought about time. So if we need an > additional sentence or two to clarify, I would encourage you to add them...If a D program wishes to determine the runtime of a program that may have started before the D program did, would it adding up the microstate times be a good way to get the actual run time? It seems as though this would catch the monotonic time, but perhaps I have a misunderstanding of how microstate counters are incremented. -- Mike Gerdts http://mgerdts.blogspot.com/
On Thu, 2007-12-20 at 13:28 -0800, Bryan Cantrill wrote:> > >> Given the documentation I would consider this to be a bug. And a > > >> pretty nasty one at that. I think if the consensus is that it is, indeed > > >> a bug, the least we can do is to put a note on our Wiki. > > >> > > >> Would anybody from team DTrace care to comment? > > > > > > This is not a bug at all -- this is the difference between gethrtime(3C) > > > and gettimeofday(3C). (If you write a program that does gethrtime() and > > > gettimeofday() for extended periods of time, you should see the same > > > degree of divergence as the D program. If you don''t, then that is a bug.) > > > In terms of the difference here, I think the documentation is actually > > > reasonably clear on this; from http://wikis.sun.com/display/DTrace/Variables: > > > > > > 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. > > > > > > walltimestamp The current number of nanoseconds since 00:00 Universal > > > Coordinated Time, January 1, 1970. > > > > I think after reading this, a reasonable expectation would be that these > > two increment "in lockstep" most of the time > > I disagree; I don''t think that is a resonable expectation -- it''s certainly > not supported by the documentation anyway. (If anything the warning next to > timestamp should dissuade such expectations.)Perhaps if we designate walltimestamp as a manifestation of the kind of functionality that gettimeofday(3C) provides I would completely agree with your viewpoint and my only concern will be reduced to the documentation issue. That, however, doesn''t really help in solving the problem that I have on my hands -- how do I determine the lifetime of the process that was started before the D script? Granted, I''m not a kernel developer so it could be that there''s such a way and I would love to be educated on what it is. At the moment, however, I''m really stuck :-( Thanks, Roman.
[...]> That, however, doesn''t really help in solving the > problem that I have > n my hands -- how do I determine the lifetime of the > process that > was started before the D script? Granted, I''m not a > kernel developer > so it could be that there''s such a way and I would > love to be educated > on what it is.Is curpsinfo->pr_start of any use (assuming I read the docs right, never tried this)? You may have to convert it to something more useful, i.e. multiply the tv_sec by a billion and then add the tv_nsec. See proc(4) for more info on struct psinfo (aka psinfo_t). -- This message posted from opensolaris.org
On 21 Dec 2007, at 00:50, Mike Gerdts wrote:> If a D program wishes to determine the runtime of a program that may > have started before the D program did, would it adding up the > microstate times be a good way to get the actual run time?Yes, but we keep track of the microstate data on a per-LWP basis. When the kernel wants to know the usage of a process, it sums the usage of the running LWPs, using mstate_aggr_state(), and adds that to the cumulative total for LWPs that have died (held in the proc_t''s p_acct[] ). If you want to track the process''s cumulative usage as it dies then you could perform the calculation from within proc_exit(), e.g. at the call to exacct_commit_proc(), where the process has but one LWP. Alternatively, you could enable the extended accounting subsystem. Robert
On 12/21/07, Richard L. Hamilton <rlhamil at smart.net> wrote:> [...] > > That, however, doesn''t really help in solving the > > problem that I have > > n my hands -- how do I determine the lifetime of the > > process that > > was started before the D script? Granted, I''m not a > > kernel developer > > so it could be that there''s such a way and I would > > love to be educated > > on what it is. > > Is curpsinfo->pr_start of any use (assuming I read the docs right, never > tried this)? You may have to convert it to something more useful, > i.e. multiply the tv_sec by a billion and then add the tv_nsec. > See proc(4) for more info on struct psinfo (aka psinfo_t).It seems like that should be useful. If you look at ptime, it does something similar, but it''s using the pr_create field of the prusage_t structure (pr_term - pr_create (subtracted as timestruct_t''s) for a process started by ptime or gethrtime() (converted to a timestruct_t) - pr_create for an extant process with the "-p <pid>" option which should soon be putback into OpenSoalris.) Chad
On 12/21/07, Chad Mynhier <cmynhier at gmail.com> wrote:> On 12/21/07, Richard L. Hamilton <rlhamil at smart.net> wrote: > > [...] > > > That, however, doesn''t really help in solving the > > > problem that I have > > > n my hands -- how do I determine the lifetime of the > > > process that > > > was started before the D script? Granted, I''m not a > > > kernel developer > > > so it could be that there''s such a way and I would > > > love to be educated > > > on what it is. > > > > Is curpsinfo->pr_start of any use (assuming I read the docs right, never > > tried this)? You may have to convert it to something more useful, > > i.e. multiply the tv_sec by a billion and then add the tv_nsec. > > See proc(4) for more info on struct psinfo (aka psinfo_t). > > It seems like that should be useful. If you look at ptime, it does > something similar, but it''s using the pr_create field of the prusage_t > structure (pr_term - pr_create (subtracted as timestruct_t''s) for a > process started by ptime or gethrtime() (converted to a timestruct_t) > - pr_create for an extant process with the "-p <pid>" option which > should soon be putback into OpenSoalris.)Doh! I should have paid more attention to the start of this thread. Using curpsinfo->pr_start is what the OP (Roman) did. I guess the ideal thing in this case would be if we exposed the prusage structure (curprusage?) so that we could use timestamp and curprusage->pr_create. (I''m just throwing this out there, I haven''t looked yet to see if there''s some way to access that or if it would be reasonable or practical to expose that structure.) Chad
Chad Mynhier wrote:> I guess the ideal thing in this case would be if we exposed the > prusage structure (curprusage?) so that we could use timestamp and > curprusage->pr_create. (I''m just throwing this out there, I haven''t > looked yet to see if there''s some way to access that or if it would be > reasonable or practical to expose that structure.)The prusage structure is populated on demand by procfs. There''s enough work involved in doing this that I''d say it''d be a lot more efficient to fish out just what you need. Regards, Robert
On Fri, 2007-12-21 at 03:00 -0800, Richard L. Hamilton wrote:> [...] > > That, however, doesn''t really help in solving the > > problem that I have > > n my hands -- how do I determine the lifetime of the > > process that > > was started before the D script? Granted, I''m not a > > kernel developer > > so it could be that there''s such a way and I would > > love to be educated > > on what it is. > > Is curpsinfo->pr_start of any use (assuming I read the docs right, never > tried this)? You may have to convert it to something more useful, > i.e. multiply the tv_sec by a billion and then add the tv_nsec. > See proc(4) for more info on struct psinfo (aka psinfo_t).Well, that was the idea. The problem however is that unless a discrepancy in the range on 0.1 seconds is acceptable there''s not way one cat determine the value of "now". Thanks, Roman.
On Fri, 2007-12-21 at 11:29 -0500, Chad Mynhier wrote:> On 12/21/07, Chad Mynhier <cmynhier at gmail.com> wrote: > > On 12/21/07, Richard L. Hamilton <rlhamil at smart.net> wrote: > > > [...] > > > > That, however, doesn''t really help in solving the > > > > problem that I have > > > > n my hands -- how do I determine the lifetime of the > > > > process that > > > > was started before the D script? Granted, I''m not a > > > > kernel developer > > > > so it could be that there''s such a way and I would > > > > love to be educated > > > > on what it is. > > > > > > Is curpsinfo->pr_start of any use (assuming I read the docs right, never > > > tried this)? You may have to convert it to something more useful, > > > i.e. multiply the tv_sec by a billion and then add the tv_nsec. > > > See proc(4) for more info on struct psinfo (aka psinfo_t). > > > > It seems like that should be useful. If you look at ptime, it does > > something similar, but it''s using the pr_create field of the prusage_t > > structure (pr_term - pr_create (subtracted as timestruct_t''s) for a > > process started by ptime or gethrtime() (converted to a timestruct_t) > > - pr_create for an extant process with the "-p <pid>" option which > > should soon be putback into OpenSoalris.) > > Doh! I should have paid more attention to the start of this thread. > Using curpsinfo->pr_start is what the OP (Roman) did. > > I guess the ideal thing in this case would be if we exposed the > prusage structure (curprusage?) so that we could use timestamp and > curprusage->pr_create. (I''m just throwing this out there, I haven''t > looked yet to see if there''s some way to access that or if it would be > reasonable or practical to expose that structure.)<me showing that I''m not a kernel engineer> My ideal scenario would be to get a hold of exactly the same variable from which curpsinfo->pr_start gets initialized by the kernel. </me showing that I''m not a kernel engineer> Thoughts? Thanks, Roman.