The Speed of Time

> 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.

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.

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...

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.

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.

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.

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.

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

The speed of time is 1 second per second