From owner-freebsd-current@FreeBSD.ORG Sat Jun 20 16:30:18 2009 Return-Path: Delivered-To: freebsd-current@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id 11814106564A for ; Sat, 20 Jun 2009 16:30:18 +0000 (UTC) (envelope-from serenity@exscape.org) Received: from ch-smtp01.sth.basefarm.net (ch-smtp01.sth.basefarm.net [80.76.149.212]) by mx1.freebsd.org (Postfix) with ESMTP id 981328FC0C for ; Sat, 20 Jun 2009 16:30:17 +0000 (UTC) (envelope-from serenity@exscape.org) Received: from c83-253-252-234.bredband.comhem.se ([83.253.252.234]:33438 helo=mx.exscape.org) by ch-smtp01.sth.basefarm.net with esmtp (Exim 4.69) (envelope-from ) id 1MI3S0-00058n-3W for freebsd-current@freebsd.org; Sat, 20 Jun 2009 18:29:58 +0200 Received: from [192.168.1.5] (macbookpro [192.168.1.5]) (using TLSv1 with cipher AES128-SHA (128/128 bits)) (No client certificate requested) by mx.exscape.org (Postfix) with ESMTPSA id C5F4218AD for ; Sat, 20 Jun 2009 18:29:53 +0200 (CEST) Message-Id: <668B820A-AAA7-4A40-8CF5-7DDCFDCD95FC@exscape.org> From: Thomas Backman To: FreeBSD current Content-Type: text/plain; charset=US-ASCII; format=flowed; delsp=yes Content-Transfer-Encoding: 7bit Mime-Version: 1.0 (Apple Message framework v935.3) Date: Sat, 20 Jun 2009 18:29:51 +0200 X-Mailer: Apple Mail (2.935.3) X-Originating-IP: 83.253.252.234 X-Scan-Result: No virus found in message 1MI3S0-00058n-3W. X-Scan-Signature: ch-smtp01.sth.basefarm.net 1MI3S0-00058n-3W a2b1f9dd313bd6239f2a980302855a88 Subject: DTrace "timestamp" wraps at about 2^33 (64-bit value)? X-BeenThere: freebsd-current@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Discussions about the use of FreeBSD-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Sat, 20 Jun 2009 16:30:18 -0000 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