New toy: attic/clocks.c - time sink warning
Hal Murray
hmurray at megapathdsl.net
Tue Jan 8 12:06:57 UTC 2019
One of the corners I'm trying to understand is the clock fuzzing. I think
it's leftover from when system time went tick, tick, tick, in big steps, say
10 ms. On modern systems, the system clock uses a register clocked by a high
speed clock, often the main CPU clock.
Please play with it and let me know if you find anything interesting. It gets
built by default, so all you have to do is run
./build/main/attic/clocks
This is long with lots of cut/paste. I may have fatfingered something.
What I've found so far:
This is typical of a reasonably modern Intel CPU
model name : Intel(R) Core(TM) i3-2120 CPU @ 3.30GHz
res avg min dups CLOCK
1 25 19 CLOCK_REALTIME
1000000 6 1000011 -10 CLOCK_REALTIME_COARSE
1 20 19 CLOCK_MONOTONIC
1 299 292 CLOCK_MONOTONIC_RAW
1 302 297 CLOCK_BOOTTIME
The res column is the result from clock_getres()
The dups column counts pairs of samples with the same answer. When negative
it counts the pairs of samples that were not not the same.
Histogram: CLOCK_REALTIME, 5 ns per bucket, 1000000 samples.
ns hits
19 999760
24 103
29 82
34 18
39 2
35 samples were bigger than 44.
You can get more detail on the histogram by hacking the code. I tuned things
so that it doesn't print out too much. My opinion, YMMV, etc. What works
well on one system can be horribly verbose on another.
>From that system:
ns hits
19 421193
20 415263
21 163248
22 19
23 20
24 19
25 20
...
23 samples were bigger than 59.
So almost all the samples are less than 22 ns.
--------
Pi 2, Linux
res avg min dups CLOCK
1 218 156 CLOCK_REALTIME
10000000 127 9999951 -12 CLOCK_REALTIME_COARSE
1 183 156 CLOCK_MONOTONIC
1 683 625 CLOCK_MONOTONIC_RAW
1 1043 989 CLOCK_BOOTTIME
Histogram: CLOCK_REALTIME, 5 ns per bucket, 1000000 samples.
ns hits
156 12705
206 964751
256 12085
261 8415
311 15
2029 samples were bigger than 316.
Note the big steps between the buckets. That's not the time to read the clock, it's a quirk of the measurement system. The clock is ticking in big steps and that shows up here.
Note that clock_getres() on NetBSD and FreeBSD (below) return the tick size rather than the resolution of timespec. Anybody know where the language lawyers for this stuff hang out?
Pi 2, NetBSD:
res avg min dups CLOCK
52 676 572 CLOCK_REALTIME
52 655 572 CLOCK_MONOTONIC
Histogram: CLOCK_REALTIME, 5 ns per bucket, 1000000 samples.
ns hits
622 298572
677 698432
727 2894
777 11
832 12
79 samples were bigger than 837.
Pi 2, FreeBSD:
res avg min dups CLOCK
53 348 312 CLOCK_REALTIME
53 318 312 CLOCK_MONOTONIC
Histogram: CLOCK_REALTIME, 5 ns per bucket, 1000000 samples.
ns hits
312 117933
362 869737
412 3846
417 7755
467 223
506 samples were bigger than 472.
Pi 1, Linux:
res avg min dups CLOCK
1 974 999 65118 CLOCK_REALTIME
10000000 765 9999690 -84 CLOCK_REALTIME_COARSE
1 985 999 52783 CLOCK_MONOTONIC
1 953 1000 68144 CLOCK_MONOTONIC_RAW
1 1427 999 CLOCK_BOOTTIME
Histogram: CLOCK_REALTIME, 5 ns per bucket, 1000000 samples.
ns hits
999 910268
1999 6075
623 samples were bigger than 2249.
Note lots of dups.
The min column filters out the dups that would be 0.
Looks like it is using a 1 microsecond clock.
The average time to read the clock is a lot slower than on a Pi 2.
---------
Linux:
model name : Intel(R) Atom(TM) CPU 230 @ 1.60GHz
res avg min dups CLOCK
1 124 120 CLOCK_REALTIME
1000000 51 999956 -47 CLOCK_REALTIME_COARSE
1 121 120 CLOCK_MONOTONIC
1 651 623 CLOCK_MONOTONIC_RAW
1 747 721 CLOCK_BOOTTIME
Histogram: CLOCK_REALTIME, 1 ns per bucket, 1000000 samples.
ns hits
120 452793
121 119686
127 117985
128 306857
135 1070
136 326
142 38
143 120
150 149
151 57
157 56
158 164
165 148
166 55
172 29
467 samples were bigger than 173.
Note the gaps from 122-126 and 128-134. The clock is ticking over that. I haven't figured out what the actual rate is. It's somewhere close to 7 ns.
NetBSD:
model name : Intel(R) Atom(TM) CPU 230 @ 1.60GHz
res avg min dups CLOCK
69 1505 1466 CLOCK_REALTIME
69 1467 1396 CLOCK_MONOTONIC
Histogram: CLOCK_REALTIME, 1 ns per bucket, 1000000 samples.
ns hits
1466 191465
1467 368026
1536 202643
1537 201860
1606 15890
1607 8133
1676 7102
1677 1590
3291 samples were bigger than 1716.
The clock is ticking in 69-70 ns ticks. Same hardware as above. ???
FreeBSD:
CPU: Intel(R) Atom(TM) CPU 230 @ 1.60GHz (1596.93-MHz 686-class CPU)
res avg min dups CLOCK
1 222 217 CLOCK_REALTIME
1 224 210 CLOCK_MONOTONIC
Histogram: CLOCK_REALTIME, 5 ns per bucket, 1000000 samples.
ns hits
217 530259
222 460091
232 1695
237 433
247 386
7136 samples were bigger than 252.
--------
This is the same core as above, but 2 cores in the package rather than 1. Note the average time is much slower. I'd guess that's the time for some sort of coordination with the other core.
Linux:
model name : Intel(R) Atom(TM) CPU 330 @ 1.60GHz
res avg min dups CLOCK
1 1039 698 CLOCK_REALTIME
1000000 70 999985 -66 CLOCK_REALTIME_COARSE
1 1038 629 CLOCK_MONOTONIC
1 1028 768 CLOCK_MONOTONIC_RAW
1 1054 768 CLOCK_BOOTTIME
Histogram: CLOCK_REALTIME, 5 ns per bucket, 1000000 samples.
ns hits
768 8
838 23
903 1
908 17
973 79079
978 274343
1043 242894
1048 392446
1113 3997
1118 3287
1183 777
1188 349
...
1184 samples were bigger than 2018.
NetBSD:
res avg min dups CLOCK
69 2866 2793 CLOCK_REALTIME
69 2838 2793 CLOCK_MONOTONIC
Histogram: CLOCK_REALTIME, 5 ns per bucket, 1000000 samples.
ns hits
2793 88684
2863 790368
2933 93098
3003 22455
3068 212
5183 samples were bigger than 3073.
FreeBSD:
res avg min dups CLOCK
1 171 157 CLOCK_REALTIME
1 163 157 CLOCK_MONOTONIC
Histogram: CLOCK_REALTIME, 5 ns per bucket, 1000000 samples.
ns hits
157 85923
162 890202
172 8362
177 14868
187 37
608 samples were bigger than 192.
Interesting that it is so much faster than Linux or FreeBSD.
--
These are my opinions. I hate spam.
More information about the devel
mailing list