www.fabiankeil.de/gehacktes/dtrace-timestamp-tests/
The following two scripts where used to evaluate various ways to implement DTrace walltimestamp support for FreeBSD.
They are still useful to get an idea of how reliably timestamp and walltimestamp work with a given system configuration.
fk@r500 ~ $sudo ~/scripts/timestamp-deltas.d
---------------------------------
Elapsed walltimestamp nanoseconds: 1000001536 (off by -1536)
Elapsed timestamp nanoseconds: 999994469 (off by 5531)
Difference in deltas this second: 7067 nanoseconds.
Difference in deltas since trace start: 298151 nanoseconds.
---------------------------------
Elapsed walltimestamp nanoseconds: 1000000699 (off by -699)
Elapsed timestamp nanoseconds: 999974430 (off by 25570)
Difference in deltas this second: 26269 nanoseconds.
Difference in deltas since trace start: 324420 nanoseconds.
---------------------------------
Elapsed walltimestamp nanoseconds: 1000001676 (off by -1676)
Elapsed timestamp nanoseconds: 999976003 (off by 23997)
Difference in deltas this second: 25673 nanoseconds.
Difference in deltas since trace start: 350093 nanoseconds.
^C
---------------------------------
Elapsed walltimestamp nanoseconds: 1000000978 (off by -978)
Elapsed timestamp nanoseconds: 999974811 (off by 25189)
Difference in deltas this second: 26167 nanoseconds.
Difference in deltas since trace start: 376260 nanoseconds.
-------------------------------------
Elapsed seconds 5
walltimestamp_off
value ------------- Distribution ------------- count
-2048 | 0
-1024 |@@@@@@@@@@@@@@@@@@@@ 2
-512 |@@@@@@@@@@@@@@@@@@@@ 2
-256 | 0
timestamp_off
value ------------- Distribution ------------- count
2048 | 0
4096 |@@@@@@@@@@ 1
8192 | 0
16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3
32768 | 0
avg_walltimestmap_off -1222
avg_abs_walltimestmap_off 1222
avg_abs_timestmap_off 20071
avg_timestmap_off 20071
It's somewhat obvious that using walltimestamp deltas might not be the best idea because they are more expensive than timestamp deltas. This script additionally shows that walltimestamp deltas can't be used (on FreeBSD) to measure short intervals at all, as the walltimestamp source doesn't tick often enough.
The good news is that the walltime doesn't go backwards which would be even worse.
fk@r500 ~ $sudo ~/scripts/timestamp-sanity-checks.d ^C -------------- 2013 Jan 23 17:24:46 -------------- walltimestamp: forward 25388 no change 616478 total 641867 timestamp: forward 641866 total 641867
If you care about this, you could try one of the earlier implementations which uses a per-cpu timestamp cache that is updated more frequently, but is more expensive and thus can skew results differently.
timestamp-test.d can be used to test if timestamp deltas can be trusted:
fk@r500 ~ $sudo ~/scripts/timestamp-test.d
Password:
Probe fired at 2013 Jan 23 17:33:16, 999 ms after the previous one.
Probe fired at 2013 Jan 23 17:33:17, 999 ms after the previous one.
Probe fired at 2013 Jan 23 17:33:18, 999 ms after the previous one.
Probe fired at 2013 Jan 23 17:33:19, 999 ms after the previous one.
Probe fired at 2013 Jan 23 17:33:20, 999 ms after the previous one.
Probe fired at 2013 Jan 23 17:33:21, 999 ms after the previous one.
Probe fired at 2013 Jan 23 17:33:22, 999 ms after the previous one.
Probe fired at 2013 Jan 23 17:33:23, 999 ms after the previous one.
^C
Probe fired at 2013 Jan 23 17:33:24, 999 ms after the previous one.
elapsed
value ------------- Distribution ------------- count
980 | 0
990 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 9
1000 | 0
elapsed avg 999
On my system the timer used for timestamp doesn't tick when the CPU is in C3 state. The problem report contains a naive patch that fixes this, but causes the kernel to crash if you aren't holding it right.
I currently use a script to disable C3 states when loading the dtrace kernel modules, otherwise timed operations appear to be faster than they are, except when the system is under heavy load that prevents the CPU from going into C3 state. Example:
fk@r500 ~ $sudo sysctl hw.acpi.cpu.cx_lowest=C3
hw.acpi.cpu.cx_lowest: C2 -> C3
fk@r500 ~ $sudo ~/scripts/timestamp-test.d
Probe fired at 2013 Jan 23 17:36:22, 228 ms after the previous one.
Probe fired at 2013 Jan 23 17:36:23, 256 ms after the previous one.
Probe fired at 2013 Jan 23 17:36:24, 319 ms after the previous one.
Probe fired at 2013 Jan 23 17:36:25, 274 ms after the previous one.
Probe fired at 2013 Jan 23 17:36:26, 253 ms after the previous one.
Probe fired at 2013 Jan 23 17:36:27, 258 ms after the previous one.
Probe fired at 2013 Jan 23 17:36:28, 293 ms after the previous one.
Probe fired at 2013 Jan 23 17:36:29, 313 ms after the previous one.
Probe fired at 2013 Jan 23 17:36:30, 263 ms after the previous one.
Probe fired at 2013 Jan 23 17:36:31, 301 ms after the previous one.
Probe fired at 2013 Jan 23 17:36:32, 276 ms after the previous one.
^C
Probe fired at 2013 Jan 23 17:36:33, 232 ms after the previous one.
elapsed
value ------------- Distribution ------------- count
210 | 0
220 |@@@ 1
230 |@@@ 1
240 | 0
250 |@@@@@@@@@@ 3
260 |@@@ 1
270 |@@@@@@@ 2
280 | 0
290 |@@@ 1
300 |@@@ 1
310 |@@@@@@@ 2
320 | 0
elapsed avg 272
fk@r500 ~ $sysctl dev.cpu.1.cx_usage
dev.cpu.1.cx_usage: 0.00% 8.84% 91.15% last 1100us