Can you trust times shown in the log?
Next to the order of entries in the log, their date and time stamps are one of the most important pieces of information they contain. In some cases, such as when you’re using the log to estimate performance, their accuracy is vital. This article reports the results from tests to validate the times given in log records provided by the log show
command, and in my free log browsers LogUI and Ulbow.
Clock date and time
Dates and times given in log extracts invariably match those of the Mac’s system clock, the only catch here being adjustments for time zone and DST. The latter can become confusing if you look at the log when DST is changed, or from a different time zone. To cope with that you can use the --timezone local
option in log show
to express all times with uniform adjustment. Ulbow doesn’t use that, but LogUI does now synchronise all time and date stamps to the current time zone and DST.
Time differences
The log is an excellent tool for measuring time and performance, either using regular entries or Signposts that are intended for the purpose. Writing an entry into the log incurs minimal overhead, and is simple to perform from any code or script. If your favourite scripting language doesn’t give direct access to writing entries, then you can use my free command tool blowhole
to do so. If you want to assess processes in macOS, then it’s usually straightforward to identify appropriate milestones that mark events and use those to calculate the period. These all depend on the times reported in log entries being sufficiently accurate.
Gold standard
Since Mac OS X, every Mac has had a high-precision internal clock within it (prior to that Time Manager could resolve times down to the microsecond but no further). This increments monotonically in ‘ticks’, an unsigned 64-bit integer, starting from an arbitrary value, and is referred to as Mach Absolute Time (MAT).
Intel Macs increment their ‘tick’ count once every nanosecond, so the difference between two readings of the clock represents the time interval in nanoseconds. Life isn’t as simple with Apple silicon Macs, as they tick three times every 125 nanoseconds, or once every 41.67 nanoseconds. Apple’s latest documentation on MAT, its units and use, comes in a Technical Q&A dated 2005.
Once correctly converted into nanoseconds, MAT is the closest available measurement of time to a gold standard.
I suspect that log entries are originally given a raw MAT as their time, and that can be made available using the log show
command, or in Ulbow, as that uses log show
to obtain log entries. LogUI reads the log directly, through the OSLog API in macOS, which currently doesn’t provide MAT values, instead giving a lower resolution Date value.
This validation therefore compares time intervals given by Ulbow from log entry timestamps, and those given in LogUI, against MAT intervals obtained in Ulbow. To increase the challenge, log entries used are from blowhole
writing 25 log entries as fast as it can, a worst case scenario as that writes 2-3 entries each microsecond.
Comparisons
Log extracts obtained using log show
in Ulbow and those estimated by LogUI were compared, and their timestamps were found to be identical.
On an Apple silicon Mac (M4 Pro), entries written by blowhole
had raw MAT values that recorded intervals of 9 or 10 ticks between them, after the first three were made 73 and 15 ticks apart. From the third of the series of 25 log entries there was a strong linear relationship between recorded MAT in nanoseconds elapsed and loop number, as shown in the chart below.
The gradient of the regressed line shows that blowhole
‘s log entries occurred at intervals of just under 405 nanoseconds.
Because LogUI (and regular timestamps in log show
and Ulbow) only resolve to microseconds, the matching plot for LogUI’s times against loop number is stepped.
The gradient of this regression line is 0.4, indicating that the intervals occurred at 400 nanoseconds, almost identical to that found for the MAT.
Plotting times measured by LogUI (which also represents those for Ulbow and log show
, as they’re identical) against that of MAT shows a good linear relationship with a gradient of just under 1.009, indicating that timestamps in log show
, Ulbow and LogUI are accurate and reliable estimates of MAT.
Differences between pairs of time estimates obtained from MAT and LogUI ranged from -83 to +792 nanoseconds, with a median of +370 and quartiles of +83 to +583 nanoseconds.
Conclusion
- Times given for log entries in LogUI, Ulbow and
log show
are reliable estimates of MAT to within +0.8 microseconds. - When nanosecond resolution is needed, the machTimestamp field from
log show
or Ulbow should be used, and converted into nanoseconds.