7 ms·

The Speed of Time

142 points by tuananh 5y ago

justinsaccount 5y ago
This can be a problem on physical machines too. Ran into an issue where on two identical machines one was showing cpu usage 30% higher. A quick `perf top` showed it was spending the majority of its time in `read_hpet` in the kernel. Found that one machine was set to hpet because the kernel thought tsc was unstable at bootup: tsc: Marking TSC unstable due to check_tsc_sync_source failed Only ever happened one time and we could never reproduce it. bios/firmware updates might have also helped. We still added a monitoring check to ensure that current_clocksource was tsc.
dboreham 5y ago
Back when I was involved with shipping server products on a raft of different Unixen, this was a major issue -- code written originally on, say Solaris, would run like a dog on HP-UX because it fetched the time constantly.
cperciva 5y ago
FreeBSD/EC2 uses TSC starting with 13.0, and this caused some issues with t3.* instances -- I'm told however that this is due to a bug in EC2 which will be fixed. TSC has been totally solid on other instance types, however. Just some data points for anyone with an interest in EC2 and clock sources...
- nucleardog 5y ago
  Ran into this the other day messing around with a Consul/Nomad cluster on FreeBSD on AWS. I kept having one of the nodes dropping out because it had missed sending its heartbeats, even though it was under next to no load and otherwise healthy. It was a head scratcher for a bit, but once I ended up figuring out what was going on it was a super obvious issue. Running `date; sleep 1;` in a loop, both were printing numbers increasing one second at a time, but one node was printing twice as fast as the other! Of course there were timing issues when two nodes couldn’t agree on something as fundamental as how long a second was. (As an aside, thank you for all your work on FreeBSD! If I ever run into you around town I owe you a beer!)
  - cperciva 5y ago
    You might be the second person to run into this. Just to confirm, you were using T3 instances? (BTW I have a Patreon for anyone who wants to contribute to my FreeBSD/EC2 work or can convince their employers to: https://www.patreon.com/cperciva https://www.patreon.com/cperciva )
    - nucleardog 5y ago
      Well don't I feel special now! Yes, t3 instances. I wasn't seeing this behaviour on _all_ of the instances. Deploying and redeploying a three node cluster a few times trying to track down what was going on never left me in a stable state though so it certainly wasn't rare. This was in us-west-2. I didn't notice if the issue correlated with the AZ or anything else, as until I figured out what was going on I naturally assumed it was an issue on my end and once I found the issue I just patched over it with `kern.timecounter.hardware=ACPI-fast` and moved on since this was just some play projects. Haven't used FreeBSD at work, but I've been using it at home and for personal hosting on AWS for the past 20 odd years. Just pledged a bit on Patreon. Thanks for all the work you put in!
      - cperciva 5y ago
        Yeah it seems random whether a t3 instance is affected or not -- rather annoyingly, when I was trying to debug this none of my instances ever ended up being affected. Using ACPI-fast is the correct workaround on 13.0, at least until the underlaying EC2 issue gets fixed. On 14.0 we have kvmclock which works fine even on instances with broken TSCs, and that's much faster than ACPI-fast -- but still slightly slower than TSC.
xyzzyz 5y ago
> A Cassandra database cluster had switched to Ubuntu and noticed write latency increased by over 30%. A quick check of basic performance statistics showed over 30% higher CPU consumption. What on Earth is Ubuntu doing that results in 30% higher CPU time!? Also, think about it this way: imagine if you started out with Ubuntu. You’d then likely never notice that your system is 30% slower than it needs be. Now, take it further: the system from which you moved to Ubuntu most likely has not been the most efficient it could get either, and it was also likely that random crap was sapping significant amount of performance. And finally, extend this from Cassandra and Ubuntu to everything else. Welcome to 2021, where machines are faster than ever, but things feel as slow as they have always been.
- bostonsre 5y ago
  Yea, this stuff is complicated. It only starts making sense to get someone like Brendan on your pay roll as your company scales and your aws bill gets larger and larger. To most small companies, that additional 30% cpu utilization is negligible and not worth the time to investigate but for someone like Netflix, having a baller like him on your team can save you millions of dollars in compute costs. But there is still hope for us mere mortals to understand how systems work better and make them faster. His systems performance book is absolutely ridiculous. It is pretty dense and I've been through chapters several times without fully grasping everything, but it is extremely pragmatic with how it dives into various topics and it is by far the best computer science book I've read.
  - tnel77 5y ago
    What book are you referring to?
    - bostonsre 5y ago
      https://www.brendangregg.com/blog/2020-07-15/systems-performance-2nd-edition.html https://www.brendangregg.com/blog/2020-07-15/systems-perform... I highly recommend it to anyone who gets close to systems.
redis_mlc 5y ago
Note the blog info is actually from 2014.
lifthrasiir 5y ago
I'm surprised that Java uses gettimeofday (equivalent to CLOCK_REALTIME in clock_gettime calls) instead of CLOCK_REALTIME_COARSE for os::javaTimeMillis(). IIRC the resolution of the coarse clock has been 1 ms since around Linux 3.0 and it can avoid most system calls even if the underlying clock source needs them. Of course it can't be used if you need sub-ms resolution, but the function name clearly suggests that it only needs millisecond resolution (as per System.currentTimeMillis) so using a plain gettimeofday seems inefficient. For the reference, glibc implementation of time() (which has 1 second resolution) internally uses coarse clocks.
- saagarjha 5y ago
  Perhaps some useful background: https://bugs.java.com/bugdatabase/view_bug.do?bug_id=JDK-8185891 https://bugs.java.com/bugdatabase/view_bug.do?bug_id=JDK-818... (historically, the blog post triggering this bug report came after this investigation, but I guess before publication.)
FpUser 5y ago
I had closely related problem in desktop application. It does some device control and works on USB interrupts at 256 or 512 invocations per sec. To account for a jitter and some other things I also inserted some time measuring calls. Inside the handler there were some calculations but I've discovered that those consume disproportionate amount of time. The investigation revealed that on multicore CPUs QueryPerformanceCounter call can take 1 microsecond. Since I had quite a few of those it added up to way too much. Ended up writing small piece of assembly that checked if invariant TSC is supported on CPU (which it is for any reasonable CPU) and replaced time measuring calls supplied by the OS to RDTSC that takes just nanoseconds. The strange thing is that where possible QueryPerformanceCounter should use just RDTSC internally accordingly to docs. By timing it it appears that at least in my case it did not.
2rsf 5y ago
As a side note I am really impressed from how the whole investigation process is well documented. I am also involved in similar detective works, but usually I tend to forget the initial parts before anyone figures out that it is an investigation
PaulHoule 5y ago
It doesn't surprise me. When I was thinking about "What could system calls look like in a clean-sheet OS?" (e.g. async-only) I always found time() was a special case that opened the door to more special cases since time() is usually almost all overhead and it often gets called often.
- yetihehe 5y ago
  Time is THE synchronous call. It is essential barrier between synchronous and asynchronous sides of your system.
- yencabulator 5y ago
  vDSO should make most calls of time not be syscalls. https://man7.org/linux/man-pages/man7/vdso.7.html https://man7.org/linux/man-pages/man7/vdso.7.html
jdlyga 5y ago
The speed of time is 1 second per second
- klyrs 5y ago
  Not if you're in an accelerating reference frame...

142 points by tuananh 5y ago

This can be a problem on physical machines too. Ran into an issue where on two identical machines one was showing cpu usage 30% higher. A quick `perf top` showed it was spending the majority of its time in `read_hpet` in the kernel. Found that one machine was set to hpet because the kernel thought tsc was unstable at bootup: tsc: Marking TSC unstable due to check_tsc_sync_source failed Only ever happened one time and we could never reproduce it. bios/firmware updates might have also helped. We still added a monitoring check to ensure that current_clocksource was tsc.

dboreham 5y ago

Back when I was involved with shipping server products on a raft of different Unixen, this was a major issue -- code written originally on, say Solaris, would run like a dog on HP-UX because it fetched the time constantly.

cperciva 5y ago

FreeBSD/EC2 uses TSC starting with 13.0, and this caused some issues with t3.* instances -- I'm told however that this is due to a bug in EC2 which will be fixed. TSC has been totally solid on other instance types, however. Just some data points for anyone with an interest in EC2 and clock sources...

nucleardog 5y ago
Ran into this the other day messing around with a Consul/Nomad cluster on FreeBSD on AWS. I kept having one of the nodes dropping out because it had missed sending its heartbeats, even though it was under next to no load and otherwise healthy. It was a head scratcher for a bit, but once I ended up figuring out what was going on it was a super obvious issue. Running `date; sleep 1;` in a loop, both were printing numbers increasing one second at a time, but one node was printing twice as fast as the other! Of course there were timing issues when two nodes couldn’t agree on something as fundamental as how long a second was. (As an aside, thank you for all your work on FreeBSD! If I ever run into you around town I owe you a beer!)
- cperciva 5y ago
  You might be the second person to run into this. Just to confirm, you were using T3 instances? (BTW I have a Patreon for anyone who wants to contribute to my FreeBSD/EC2 work or can convince their employers to: https://www.patreon.com/cperciva https://www.patreon.com/cperciva )
  - nucleardog 5y ago
    Well don't I feel special now! Yes, t3 instances. I wasn't seeing this behaviour on _all_ of the instances. Deploying and redeploying a three node cluster a few times trying to track down what was going on never left me in a stable state though so it certainly wasn't rare. This was in us-west-2. I didn't notice if the issue correlated with the AZ or anything else, as until I figured out what was going on I naturally assumed it was an issue on my end and once I found the issue I just patched over it with `kern.timecounter.hardware=ACPI-fast` and moved on since this was just some play projects. Haven't used FreeBSD at work, but I've been using it at home and for personal hosting on AWS for the past 20 odd years. Just pledged a bit on Patreon. Thanks for all the work you put in!
    - cperciva 5y ago
      Yeah it seems random whether a t3 instance is affected or not -- rather annoyingly, when I was trying to debug this none of my instances ever ended up being affected. Using ACPI-fast is the correct workaround on 13.0, at least until the underlaying EC2 issue gets fixed. On 14.0 we have kvmclock which works fine even on instances with broken TSCs, and that's much faster than ACPI-fast -- but still slightly slower than TSC.

xyzzyz 5y ago

> A Cassandra database cluster had switched to Ubuntu and noticed write latency increased by over 30%. A quick check of basic performance statistics showed over 30% higher CPU consumption. What on Earth is Ubuntu doing that results in 30% higher CPU time!? Also, think about it this way: imagine if you started out with Ubuntu. You’d then likely never notice that your system is 30% slower than it needs be. Now, take it further: the system from which you moved to Ubuntu most likely has not been the most efficient it could get either, and it was also likely that random crap was sapping significant amount of performance. And finally, extend this from Cassandra and Ubuntu to everything else. Welcome to 2021, where machines are faster than ever, but things feel as slow as they have always been.

bostonsre 5y ago
Yea, this stuff is complicated. It only starts making sense to get someone like Brendan on your pay roll as your company scales and your aws bill gets larger and larger. To most small companies, that additional 30% cpu utilization is negligible and not worth the time to investigate but for someone like Netflix, having a baller like him on your team can save you millions of dollars in compute costs. But there is still hope for us mere mortals to understand how systems work better and make them faster. His systems performance book is absolutely ridiculous. It is pretty dense and I've been through chapters several times without fully grasping everything, but it is extremely pragmatic with how it dives into various topics and it is by far the best computer science book I've read.
- tnel77 5y ago
  What book are you referring to?
  - bostonsre 5y ago
    https://www.brendangregg.com/blog/2020-07-15/systems-performance-2nd-edition.html https://www.brendangregg.com/blog/2020-07-15/systems-perform... I highly recommend it to anyone who gets close to systems.

redis_mlc 5y ago

Note the blog info is actually from 2014.

lifthrasiir 5y ago

I'm surprised that Java uses gettimeofday (equivalent to CLOCK_REALTIME in clock_gettime calls) instead of CLOCK_REALTIME_COARSE for os::javaTimeMillis(). IIRC the resolution of the coarse clock has been 1 ms since around Linux 3.0 and it can avoid most system calls even if the underlying clock source needs them. Of course it can't be used if you need sub-ms resolution, but the function name clearly suggests that it only needs millisecond resolution (as per System.currentTimeMillis) so using a plain gettimeofday seems inefficient. For the reference, glibc implementation of time() (which has 1 second resolution) internally uses coarse clocks.

saagarjha 5y ago
Perhaps some useful background: https://bugs.java.com/bugdatabase/view_bug.do?bug_id=JDK-8185891 https://bugs.java.com/bugdatabase/view_bug.do?bug_id=JDK-818... (historically, the blog post triggering this bug report came after this investigation, but I guess before publication.)

FpUser 5y ago

I had closely related problem in desktop application. It does some device control and works on USB interrupts at 256 or 512 invocations per sec. To account for a jitter and some other things I also inserted some time measuring calls. Inside the handler there were some calculations but I've discovered that those consume disproportionate amount of time. The investigation revealed that on multicore CPUs QueryPerformanceCounter call can take 1 microsecond. Since I had quite a few of those it added up to way too much. Ended up writing small piece of assembly that checked if invariant TSC is supported on CPU (which it is for any reasonable CPU) and replaced time measuring calls supplied by the OS to RDTSC that takes just nanoseconds. The strange thing is that where possible QueryPerformanceCounter should use just RDTSC internally accordingly to docs. By timing it it appears that at least in my case it did not.

2rsf 5y ago

As a side note I am really impressed from how the whole investigation process is well documented. I am also involved in similar detective works, but usually I tend to forget the initial parts before anyone figures out that it is an investigation

PaulHoule 5y ago

It doesn't surprise me. When I was thinking about "What could system calls look like in a clean-sheet OS?" (e.g. async-only) I always found time() was a special case that opened the door to more special cases since time() is usually almost all overhead and it often gets called often.

yetihehe 5y ago
Time is THE synchronous call. It is essential barrier between synchronous and asynchronous sides of your system.
yencabulator 5y ago
vDSO should make most calls of time not be syscalls. https://man7.org/linux/man-pages/man7/vdso.7.html https://man7.org/linux/man-pages/man7/vdso.7.html

jdlyga 5y ago

The speed of time is 1 second per second

klyrs 5y ago
Not if you're in an accelerating reference frame...