A Dance to the Music of Time in Intel and Apple silicon logs

Now we’ve got LogUI to give us the times of log entries down to the nearest nanosecond, it’s time to see whether that’s any improvement over other tools. Given that Mach Absolute Time resolves to nanoseconds (10^-9 seconds) in Intel Macs, and just under 42 nanoseconds in Apple silicon Macs, can we now resolve times of events better than when using microseconds (10^-6 seconds)?

Methods

To test this out, I used my command tool blowhole that can run a tight loop writing entries in the log as fast as possible. To do this, it uses the code
for index in 1…number {
os_log(“%d”, log: Blowhole.gen_log, type: type, index)
}

I then wrote loops of 20 to the log of an iMac Pro (Intel Xeon W CPU), M3 Pro and M4 Pro, and extracted the resulting log entries using LogUI with its new nanosecond times.

Results

Plotting these times against loop number resulted in unexpected patterns.

In this graph, results from the iMac Pro are shown in black, those from the M3 Pro in blue, and the M4 Pro in red. Although less well-ordered in the first to fourth loops, from the fifth loop onwards there were linear relationships between time of log entries and loop number. Linear regression equations are shown in the legend, and demonstrate:

on the iMac Pro each loop takes 1.0 x 10^-6 seconds, i.e. 1 μs;
on the M3 Pro each loop takes 5.6 x 10^-7 seconds, i.e. 0.6 μs;
on the M4 Pro each loop takes 4.6 x 10^-7 seconds, i.e. 0.5 μs.

which perhaps isn’t surprising.

However, the patterns of individual points are quite different. Apart from loops 4 and 5, subsequent loops on the iMac Pro are evenly spaced in time. Those on the Apple silicon chips are grouped in pairs or, for loops 14-16 on the M4 Pro, in a triplet, where two or three loops are assigned the same time in the log.

Looking at time differences, a clear pattern emerges, that log times are incremented in steps of 954 ns. For the iMac Pro, each loop occurs one step later, while for the M3 Pro and M4 Pro steps between pairs and triplets are also 954 ns. In a few cases, the step difference is slightly greater at around 1192 ns instead of 954 ns. Apple silicon chips are faster on average because each step includes two or more loops, while the iMac Pro only manages one loop per step.

Explanation

If log entry times had been given in microseconds rather than nanoseconds, the same patterns would have been seen. But without the additional precision in their times, it wouldn’t have been clear that multiple log entries were being written with identical times, down to the nanosecond.

One likely explanation is that macOS only writes log entries approximately every microsecond, and the entry time recorded for each is that of that writing. Writing log entries must occur asynchronously for the M3 Pro and M4 Pro to be able to send pairs or triplets to be written, rather than having to wait for each writing process to complete.

Thus, the time resolution of log entries is approximately 1 μs, or 954 or 1192 ns to be more precise, and that’s the same regardless of whether macOS is running on a recent Intel Mac or the latest Apple silicon chips. Although a time resolution of 1 μs is sufficient for general purposes, if you want to dig deeper, as I have done here, access to the finer resolution provided in nanosecond times is essential.

Conclusions

Times written in log entries are incremented every 954 or 1192 ns on both Intel and Apple silicon.
Faster Apple silicon chips can write more than one entry in the same time increment.
Although expressing the time of log entries in microseconds is sufficient for general purposes, using nanoseconds can confirm which have occurred simultaneously.

The Music of Time

So what is a Dance to the Music of Time? It’s one of Nicolas Poussin’s most brilliant paintings, that inspired a series of twelve novels written by Anthony Powell. While I wouldn’t attempt to summarise those, here’s the painting to enjoy.

Nicolas Poussin (1594–1665), A Dance to the Music of Time (c 1634-6), oil on canvas, 82.5 × 104 cm, The Wallace Collection, London. Wikimedia Commons.

Poussin’s Dance to the Music of Time (c 1634-6) shows four young people dancing, who are currently believed to be Poverty (male at the back, facing away), Labour (closest to Time and looking at him), Wealth (in golden skirt and sandals, also looking at Time), and Pleasure (blue and red clothes) who fixes the viewer with a very knowing smile. Opposite Pleasure is a small herm of Janus, whose two faces look to the past and the future. Father Time at the right is playing his lyre to provide the music, and an infant seated by him holds a sandglass, to measure time periods. Above them in the heavens, Aurora (goddess of the dawn) precedes Apollo’s sun chariot, on which the large ring represents the Zodiac, thus the passage of the months. Behind the chariot are the Horai, the four seasons of the year.