Date: Sat, 20 Jun 2009 18:29:51 +0200 From: Thomas Backman <serenity@exscape.org> To: FreeBSD current <freebsd-current@freebsd.org> Subject: DTrace "timestamp" wraps at about 2^33 (64-bit value)? Message-ID: <668B820A-AAA7-4A40-8CF5-7DDCFDCD95FC@exscape.org>
next in thread | raw e-mail | index | archive | help
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@chaos /]# dtrace -n 'syscall:::entry { self->pf = probefunc;
self->ts = timestamp; } syscall:::return /self->ts/ { @a[self->pf] =
quantize(timestamp - self->ts); }'
dtrace: description 'syscall:::entry ' matched 1002 probes
^C
select
value ------------- Distribution ------------- count
-8589934592 | 0
-4294967296 |@@ 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 |@@@@@@@ 15
4096 |@@@@@@@@@@@@@@ 29
8192 |@ 3
16384 | 0
32768 | 0
65536 |@@@ 7
131072 |@ 3
....
Also:
[root@chaos /]# dtrace -n 'syscall:::entry { self->pf = probefunc;
self->ts = timestamp; } syscall:::return /self->ts/ { @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,
Thomas
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?668B820A-AAA7-4A40-8CF5-7DDCFDCD95FC>