DTrace "timestamp" wraps at about 2^33 (64-bit value)?

From: Thomas Backman <serenity_at_exscape.org>
Date: Sat, 20 Jun 2009 18:29:51 +0200
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,
Thomas
Received 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