It appears the DTrace "timestamp" variable is wrapping around way, way too quickly - it only goes to somewhere slightly above 2^33 (in practice, at least), and since it's in nanoseconds, that's not a lot. (2^33 ns is less than 10 seconds, actually. 2^64 is 584.55 years, however!) # dtrace -n 'tick-500ms { trace(timestamp); }' dtrace: description 'tick-500ms ' matched 1 probe CPU ID FUNCTION:NAME 0 40770 :tick-500ms 8217926898 0 40770 :tick-500ms 8717920699 0 40770 :tick-500ms 37092920 0 40770 :tick-500ms 537090983 0 40770 :tick-500ms 1037086239 0 40770 :tick-500ms 1537081743 0 40770 :tick-500ms 2037075002 0 40770 :tick-500ms 2537073505 0 40770 :tick-500ms 3037066771 0 40770 :tick-500ms 3536065278 0 40770 :tick-500ms 4036058122 0 40770 :tick-500ms 4536056423 0 40770 :tick-500ms 5036049344 0 40770 :tick-500ms 5536047746 0 40770 :tick-500ms 6036041477 0 40770 :tick-500ms 6536039244 0 40770 :tick-500ms 7036033423 0 40770 :tick-500ms 7536030678 0 40770 :tick-500ms 8036025843 0 40770 :tick-500ms 8536020127 0 40770 :tick-500ms 9036012808 0 40770 :tick-500ms 355189205 0 40770 :tick-500ms 855182280 0 40770 :tick-500ms 1355180867 0 40770 :tick-500ms 1855173430 0 40770 :tick-500ms 2355172744 (From /usr/src/sys/cddl/dev/dtrace/amd64/dtrace_subr.c) /* * DTrace needs a high resolution time function which can * be called from a probe context and guaranteed not to have * instrumented with probes itself. * * Returns nanoseconds since boot. */ uint64_t dtrace_gethrtime() { return ((rdtsc() + tsc_skew[curcpu]) * (int64_t) 1000000000 / tsc_freq); } Is the function above really working as it should? (I'm assuming it's the function used to return the timestamp variable, here.) I ran into this in a more real-world example than tick, too: [root_at_chaos /]# dtrace -n 'syscall:::entry { self->pf = probefunc; self->ts = timestamp; } syscall:::return /self->ts/ { _at_a[self->pf] = quantize(timestamp - self->ts); }' dtrace: description 'syscall:::entry ' matched 1002 probes ^C select value ------------- Distribution ------------- count -8589934592 | 0 -4294967296 |_at__at_ 4 -2147483648 | 0 -1073741824 | 0 -536870912 | 0 -268435456 | 0 ....... 1 | 0 2 | 0 4 | 0 8 | 0 16 | 0 32 | 0 64 | 0 128 | 0 256 | 0 512 | 0 1024 | 0 2048 |_at__at__at__at__at__at__at_ 15 4096 |_at__at__at__at__at__at__at__at__at__at__at__at__at__at_ 29 8192 |_at_ 3 16384 | 0 32768 | 0 65536 |_at__at__at_ 7 131072 |_at_ 3 .... Also: [root_at_chaos /]# dtrace -n 'syscall:::entry { self->pf = probefunc; self->ts = timestamp; } syscall:::return /self->ts/ { _at_a[self->pf] = min(timestamp - self->ts); }' dtrace: description 'syscall:::entry ' matched 1002 probes ^C _umtx_op -8181214691 select -8179150768 sigprocmask 1470 fcntl 1567 lseek 1619 ... I doubt that select executes in -8.17 seconds. ;) Regards, ThomasReceived on Sat Jun 20 2009 - 14:30:18 UTC
This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:39:50 UTC