Wherever you turn in a Mac, and in macOS, clocks and time are always there. From your processor’s clock speed to the digital clock probably ticking away in your menubar, there’s no escaping it.

I have discussed before the several different clocks which are accessible in your Mac. Yesterday it was time to confront them.

Every entry in the macOS unified log, including Signposts, features two separate records of the time. One is in the recognisable format of a datestamp, such as
2018-08-19 20:35:41.991370+0100
which resolves down to one microsecond (0.000001 of a second). The other is a direct reading of the ‘Mach absolute time’ in system ticks, which is just a very large integer like
1521457734562380
That’s fine for measuring time intervals, but meaningless to a user who is browsing their log.

The reason for the log containing two records of time is that the datestamp is periodically recalibrated against external time references, whereas the Mach absolute time does drift very slowly. The log service daemon logd keeps records of syncs between the two in /private/var/db/diagnostics/timesync, although as these are in an undocumented binary format they’re not accessible even to the developer.

macOS provides developers with a suite of useful functions for working with time in a class called, perhaps inevitably, NSDate. The snag with working with this is that its resolution of time is not useful when you’re trying to deal with small time intervals: instead of resolving down to one microsecond, it’s content with a millisecond (0.001 of a second). For most purposes like scheduling calendars, that’s fine, but when you’re looking at events that can take less than one microsecond, it’s no good.

Most of my apps which work with logs, such as Consolation, don’t mess around with time. All they do is read the two different log fields containing times, and display them as text. RouteMap is different, though, as it’s for analysing performance, which is all about measuring very small intervals of time. Initially, it read the datestamp of each log entry and converted it into an NSDate, losing anything which took less than a millisecond into the silence between its ticks. Clearly, it needs to work with Mach absolute time instead.

Apple’s latest documentation on Mach absolute time, its units and use, comes in a Technical Q&A dated 2005. Although this has now been archived, no one in Apple seems to have written anything more useful on the subject since.

One problem with that article which has been pointed out repeatedly, but never corrected, is that it performs arithmetic with the unsigned 64-bit integer representing Mach absolute time without catering for any overflow. This is particularly important when scaling from these system ticks to real time units, as that may involve multiplication, which can readily require more bits than the unsigned 64-bit integer can support. One safe way to work around this is to handle the Mach absolute time as an unsigned 128-bit integer. Unfortunately, you’ll quickly discover that Swift, even version 4.2, doesn’t provide support for 128-bit integers, although it does for unsigned 64-bit integers.

Another snag with Apple’s article is that it was written when Macs still used PowerPC processors, and hasn’t been revised since the switch to Intel. PowerPC Macs used different timebase scaling factors to convert between system ticks and nanoseconds of real time. Intel Macs have (so far) used system ticks which are already in nanoseconds, any necessary scaling being performed in the call to get Mach absolute time. So not only do you not need to worry about timebase scaling any more, but you don’t need to cater for arithmetic overflow if you’re only going to be subtracting Mach absolute times from one another.

The final step in giving an app like RouteMap access to very precise times is to convert from the format provided by the unified log to the unsigned 64-bit integer value representing nanoseconds. The normal log timestamp is delivered as a String, which has to be read using a DateFormatter to turn it into an NSDate. The Mach system ticks, supplied as the machTimestamp in each log entry, comes as an NSNumber, from which you can then read its value as an unsigned 64-bit integer, so long as you promise to only subtract it, and not add or multiply.

At the end of several hours of research, here are the four lines of code which resulted:
if let json7 = dict.object(forKey: "machTimestamp") {
let json71 = json7 as! NSNumber
machtime = json71.uint64Value
}

What those lines enable, though, is something quite spectacular. Here is my Signpost testing app running through a simple sequence of writing five pairs of begin-end Signposts in macOS Mojave, viewed and analysed in RouteMap:

The time gap between successive begin and end entries in the log, shown in white text at the right, is just over 580 nanoseconds. That’s less than 0.6 of a microsecond, on a MacBook Pro with a 2.5 GHz i7. Is that quick enough for you?