What's the time?

March 4, 2024

I’ve been running some profiling on the PlainApm agent and one of the things that sometimes popped up in the stackprof output were calls to (Date)Time#iso8601. I used them to get an idea of the overall pipeline latency from the moment the event gets collected until it gets written to the DB.

It turns out that these calls are indeed quite slow, so depending on the use case, Time.now.to_f or Process.clock_gettime(Process::CLOCK_MONOTONIC) might be a faster alternative.

Here’s a micro-benchmark with some more variants thrown into the mix - the strftime format string is an equivalent to iso8601:

Time.now.to_f - float, epoch:         2157540.4 i/s
Time.now.to_f.to_s - string, epoch:    459280.3 i/s -  4.70x  slower
Time.now.utc.to_s - string, UTC:       369579.1 i/s -  5.84x  slower
Time.now.to_s - string, localtime:     296734.2 i/s -  7.27x  slower
Time.now.strftime('%FT%T.%9N%:z'):     250578.4 i/s -  8.61x  slower
Time.now.iso8601(9):                   191786.8 i/s - 11.25x  slower
DateTime.now.iso8601(9) - baseline:    146311.0 i/s - 14.75x  slower
DateTime.now.strftime('%FT%T.%9N%:z'): 135389.0 i/s - 15.94x  slower

The absolute numbers are not meaningful, as the benchmark was running inside a VM, but I’ve found the relative slowdowns to be quite consistent to when it ran on native HW.

My hunch is that DateTime#iso8601 is slow due to the string allocation/formatting, and having to take time zones into account.

What’s also interesting is that the Time’s version is faster than the DateTime’s.

Compared to that, Time.now.to_f runs surprisingly fast, but the gotcha is that the time might get rounded/truncated, so this loses some precision:

irb(main):001> now = Time.now
=> 2024-03-04 17:36:03.146909775 +0100
irb(main):002> now.strftime("%9N")
=> "146909775"
irb(main):003> Time.at(now.to_f).strftime("%9N")
=> "146909713"

For reporting an interval of time coming from the same host, the monotonic time would be a better choice, as it doesn’t suffer from backwards jumps on daylight-savings changes and NTP syncs.

It can be either called directly, with an appropriate clock type, or through a wrapper like monotime, or hitimes.

It is also much faster, even more than Time.now.to_f (about 2x):

Process.clock_gettime - monotonic: 5129510.3 i/s

But for measuring approximate latency across (hopefully) NTP-synced, geographically close hosts, a floating point timestamp will probably do the job, so that’s what I ended up using. Getting a higher accuracy, or an error estimate seems to be a rabbit hole though.

Perhaps for another time.