Time is central to any log, and with the high performance of the Unified log it’s fundamental. It’s also one of its most confusing aspects, particularly when you add time zones, seasonal clock changes, and clock synchronisation.

Clock ticks

I believe each log entry includes the Mach absolute time (MAT) when that entry was made, and those form the log’s internal timebase. However, Apple doesn’t document that, there are alternatives such as Mach continuous time, and times exposed in the public OSLog API are limited to opaque Date structures rather than MAT. In contrast, the log show command can return a numeric field named machTimestamp that does appear to contain the MAT of that log entry.

The first complication with time is that MAT differs between Intel and Apple silicon Macs. While each increment in MAT represents one nanosecond in Intel Macs, in Apple silicon chips MAT ticks occur three times every 125 nanoseconds, or once every 41.67 ns. These are monotonic, in that they always move forward, so every subsequent tick count is greater than (or equal to) the previous ones, unlike wallclock time.

I have looked in detail at how this is reflected in times shown in the log when accessed by different methods, including that now used by LogUI. In practice, this means that the finest resolution of time in LogUI is 1 microsecond, which should suffice for almost every purpose.

Wallclock time

While MAT can be useful for measuring differences in time with great precision, it doesn’t tell you the time in terms of real-world clocks, or wallclock time. Conversion between those relies on data stored in opaque timesync files stored alongside log files. Those are used to provide a wallclock time for each log entry when it’s obtained either through the log show command, or the opaque Date structure in the OSLog API that LogUI relies on. It’s here we encounter all the complexities of the wallclock, such as time zones, seasonal time corrections, and corrections to synchronise with global time references.

Times shown in log entries also need to match those set in the log browser. In practice that leaves two options for times shown in log entries: express them in the local time when they were saved to the log, or in the local time when they’re extracted from the log. By default, the log show command adopts the former, as does Ulbow because it gets its log entries using that command tool, but LogUI converts all times to local time when the log extract is obtained. log show does have an option --timezone local to synchronise entries to current local time, but that’s seldom used.

Wallclock adjustment

The only time measure that remains unaffected by system wallclock time adjustments is MAT. No matter how a wallclock time is expressed, though, there will always be a hiatus and the risk of duplicate times being given, for example with consecutive entries of
08:26:16.140474+0100
08:26:10.043353+0100 === system wallclock time adjusted
08:26:10.044335+0100

If you’re using the log to measure time, and those measurements span a wallclock adjustment, you will need to make a manual adjustment to allow for that.

Time zone and season

When times of log entries are expressed using the local time applicable when those entries were written, changes in time zone and seasonal adjustments become confusing. For example, these entries were written when the wallclock was advanced by one hour in accordance with the start of British Summer Time:
2020-03-29 01:09:22.489149+0000 361080253974026
2020-03-29 01:09:22.489160+0000 361080253985232
2020-03-29 02:09:22.522734+0100 361080253990360 === system wallclock time adjusted
2020-03-29 02:09:22.522749+0100 361080254005593
2020-03-29 02:09:22.522913+0100 361080254170158
In each case, the wallclock date and time are given first, followed by the MAT (from an Intel Mac), demonstrating that the hiatus of one hour doesn’t affect the latter.

According to convention, Summer time adjustments across Europe are made at 01:00:00 +0000 (UTC). So in the Spring, clocks are put forward from 01:00:00 regular time to 02:00:00 Summer time. In North America, changes are made at 02:00:00 local, and usually on different days. Because of the way that macOS manages time, changes to the system clock will inevitably occur shortly after the officially set time, in that case nearly ten minutes later.

To avoid this confusion, LogUI expresses wallclock and control times using local time when those entries are extracted from the log. In that case, you’d see
2020-03-29 02:09:22.489149+0100
2020-03-29 02:09:22.489160+0100
2020-03-29 02:09:22.522734+0100 === system wallclock time adjusted
2020-03-29 02:09:22.522749+0100
2020-03-29 02:09:22.522913+0100
as you would obtain that log extract when British Summer Time was already in force.

Converting from Date values stored in log files to strings expressed in local time isn’t something an app would want to repeat constantly, for example on the fly when scrolling through a list of 50,000 entries. LogUI therefore converts each time into text when it fetches those log entries. If you then save the log extract in JSON format, those times remain in that local form, and aren’t converted again if you open that file in a different time zone or seasonal time correction. If you want to retain times in their original format, so they’ll be converted into a later time zone, for example, save the log as a logarchive, to ensure that each time will be converted into text using the local time applicable when the extract is fetched from that logarchive. That should affect few users, and only in unusual situations.

Key points

• The Unified log appears to record times in Mach absolute time, and convert those to wallclock format when accessed.
• By default, the log show command, and apps like Ulbow that use it, give the wallclock time adjusted to local time when each log entry is written. That can result in confusing time sequences.
• LogUI expresses all times in local time when log entries are extracted from the log. That makes its handling of time independent of seasonal changes, and more consistent.
• Periodic wallclock adjustments affect all wallclock times, and may need to be allowed for when measuring times from log entries.