Reading view

There are new articles available, click to refresh the page.

Inside the Unified Log 6: Difficult times

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.

bst03

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.

Inside the Unified Log 1: Goals and architecture

The introduction of Mac OS X in 2000-01 brought conventional text-based logging to the Mac, with standard logs including system.log and console.log.

console2005

With the release of macOS 10.12 Sierra in 2016, those were almost completely replaced by the Unified Log, which has continued evolving since. Intended to provide a single efficient logging mechanism for user and kernel modes, its design goals are:

  • to maximise information collection with minimum observer effect;
  • as much logging on as much of the time as possible;
  • compression of log data for efficient use of space;
  • a managed log message lifecycle;
  • designed-in privacy protection;
  • to be common across all Apple’s operating systems;
  • all legacy APIs (NSLog, asl_log_message, syslog, etc.) to be redirected into the single log;
  • to support debugging, but not system administration or audit.

To achieve this, log entries are written using the OSLog API (or Logger from Swift), handled by the logd daemon and compressed into a buffer. From there entries are either retained in memory if intended to be ephemeral, or written out to a file. Log entries are only made from the start of kernel boot; earlier phases of the boot process instead save breadcrumbs that are largely inaccessible and unintelligible.

mul102LogdFlow

Performance of writing log entries is excellent, with a single process able to write sequential entries every 400 ns from a code loop, a rate of 2.5 million entries per second, although that rate is unlikely to be sustainable for long.

Log storage

There are two main groups of files that store log entries: those kept in /var/db/diagnostics/Persist/ in the form of tracev3 files containing regular log entries, and further tracev3 files in /var/db/diagnostics/Special/ containing additional shorter-life entries. Additional and lengthier log data can instead be stored in files named by UUID in /var/db/uuidtext/, and there’s also support for special Signpost entries intended for performance measurement, and scope for high-volume collection.

tracev3 files use a proprietary compressed binary format that remains undocumented to this day, but has been largely reversed. Apple’s APIs don’t give direct access to their contents, only through closed-source utilities such as the log command tool and programmatically through the OSLog API. Where users want a more portable format, Apple recommends conversion to a logarchive package, although that’s also undocumented and only directly accessible using log, the Console app and some third-party utilities. Logarchives still store all log entries in tracev3 files.

Collection and retention of entries from different subsystems is configured in logging profiles, XML property lists stored in /System/Library/Preferences/Logging (read-only, in the System volume) and /Library/Preferences/Logging, which the user controls. You can create your own custom profiles, or modify them on the fly using the log command.

The logd service maintains tracev3 files and their ancillaries, weeding them to remove time-expired entries. It does so to constrain the total size of log files in the system, rather than rolling them to retain all entries for a specified period. Most ephemeral entries are weeded within 5 minutes of being written to the log, leaving persistent entries to remain for the following days, depending on the volume of new entries being written. For example, in a 3 second period of collection, when all entries were obtained within a minute of being written, 22,783 entries were found. Five minutes after they had been written, only 82% of those remained, and over 8 hours later that had fallen to 80%, or 18,309.

Log content

In contrast to traditional text-based logs, entries in the macOS log contain structured data in set fields, such as the datestamp, subsystem and log message. The number of fields available from the log command has risen from 16 to over 25, but entries are constrained in which fields are available, according to their type. Currently there are four types, Regular, Activity, Boundary and Signpost.

Some log entries, notably those written to /var/db/uuidtext/, can have very long message fields, extending to dozens of lines. Among the most verbose is the com.apple.runningboard subsystem, which not infrequently writes the whole of its records for an app into the message field of a single log entry.

Privacy

Privacy protection censors content of log entries when they’re written, replacing sections of the message field with <private> in accordance with the formatting string for that message. This protection can be disabled, but as entries are censored when they’re written, that only affects those written after censorship has been removed, and can’t be applied retrospectively.

One significant change in macOS 26 Tahoe is that the message contents of all log entries written using the old NSLog interface are replaced with <private>, rendering them essentially useless. Since macOS 10.12.4, all access to log entries has required admin privileges.

Access

macOS provides users with two means of accessing entries in the log: the log command tool, and Console app. In common use, log generates text output, so losing the original data fields, one of the major advantages of the Unified Log. Console offers two methods of access: a live stream of entries, or browsing past entries in a saved logarchive.

I have four main tools that provide extensive log access:

  • LogUI, using the OSLog API and displaying entries as formatted SwiftUI Lists;
  • Mints, offering special-purpose browsers for Time Machine, APFS, and other domains;
  • Ulbow, using the log tool and displaying entries as formatted Rich Text using AppKit;
  • Consolation, using the log tool and displaying entries as formatted Rich Text using AppKit.

These are available from their product page, and here for Mints.

❌