Since its introduction in 2016 in macOS Sierra, the Unified log in macOS has been completely unlike that in traditional Unix systems. Logging takes place at a kernel level, can’t be turned off, contains structured fields of information, is high capacity, and highly responsive. While individual apps and services can still run their own logs, all macOS logs are entered into the same compressed binary log files. At any time, these contain around 17.5 million entries, vast amounts of detail about events that have taken place in macOS. This article explains how they work, and what you are dealing with when you access them.
History
Until the release of macOS Sierra in September 2016, OS X used conventional text-based logs, much like any Unix system. These were becoming cluttered up with a lot of entries from the system, and accessing them was growing increasingly difficult. From macOS 10.12 onwards, these are consolidated into a Unified log.
At first, rates of writing log entries into this new system were relatively low, and it was common for Macs running Sierra to retain log records going back twenty days or more. Because log files are automatically maintained to remain within a specified size, rather than kept for a number of days, as log entries have increased in frequency, by macOS Ventura the logs of some Macs only go back a day or less.
Fields available in entries have also grown, from 16 in Sierra to at least 28 in Ventura. In addition to including the data normally seen in traditional logs, they now contain formatString
, for instance, which gives the format string used to convert variable content into a string for output. That was added for Apple’s internal purposes following unintended leaks of passwords in the log.
Development of the Unified log has almost exclusively been driven by Apple’s requirements to provide more information for its engineers to develop and improve macOS.
Log files
Unified log files are stored in /var/db/diagnostics, on the writeable Data volume of the active boot volume group, in a fixed folder layout shown below. Regular tracev3 log files are to be found in the Persist folder, those for Signposts in its folder, and Special contains supplementary material. Although there’s also a HighVolume folder, I have never seen it being used. Often forgotten when considering the log are ancillary files in /var/db/uuidtext, and time synchronisation data in /var/db/diagnostics/timesync, both of which are required for log access to function properly.
Apple’s log file format, tracev3, is proprietary, binary and highly compressed, and has never been publicly documented by Apple. The format has evolved over the years, and it remains wisest to access log archives on macOS which is at least the same version as that responsible for writing them, to eliminate any issues of compatibility.
Types of log entries
Although they may appear homogenous, there are currently three major types of log entry:
- regular, used for the great majority of entries, with an eventType of logEvent;
- signposts, intended for measuring performance, with a signpostID and an eventType of signpostEvent;
- activities, with an eventType of activityCreateEvent.
Ulbow lets the user select which they wish to see in the current extract, set in its View menu. In addition, a style may need to include the eventType field.
Entry fields
These currently include:
- timestamp, in full e.g. 2017-07-26 20:24:59.326229+0100
- machTimestamp, in system ticks, e.g. 608403543041193
- messageType, e.g. Default
- category, e.g. security_exception
- subsystem, e.g. com.apple.securityd
- processUniqueID, e.g. 156
- threadID, e.g. 868
- traceID, e.g. 833721519476834308
- senderProgramCounter, e.g. 193733726
- processID, e.g. 156
- eventMessage, e.g. MacOS error: -67062
- processImagePath, e.g. /usr/libexec/taskgated
- processImageUUID, e.g. 4F6F0B24-7A18-3AF9-853F-8F72F6C7D7C7
- senderImagePath, e.g. /System/Library/Frameworks/Security.framework/Versions/A/Security
- senderImageUUID, e.g. 005E8C96-40B6-35E3-B58B-888A5F5957C2
- timezoneName, may be blank.
- eventType, one of signpostEvent, activityCreateEvent, logEvent, or timesyncEvent (others such as traceEvent and activityTransitionEvent may be possible but are very rare)
- signpostID, e.g. 14608112960288129006
- activityIdentifier, e.g. 32688
- parentActivityIdentifier, e.g. 0
- creatorActivityID, e.g. 0
- source, e.g. null. The only value I have ever seen for this is null.
- signpostName, a string name for a Signpost;
- signpostType, the Signpost type – begin, end, or event;
- signpostScope, a scope string, such as ‘process’;
- formatString, giving the format string used to convert variable content into a string for output, e.g. “vm_page_bootstrap: %d free pages and %d wired pages\n” or “%{public}@”;
- backtrace, consisting of imageOffset and imageUUID structured into a ‘frame’;
- bootUUID, the UUID of the last boot.
Each log entry requires a timestamp and machTimestamp, and appears to need an eventType too. Other fields appear optional, and few entries contain even half the available fields. Those accessible in Ulbow are listed in its Field Help window, available through its Help menu. They don’t currently include formatString
, or bootUUID
, which has only been introduced recently and has limited use.
Capacity
Unlike traditional log systems, which normally retain logs for a fixed period of days, the macOS log maintenance service logd
appears to weed log files to keep their total size within a set limit, which can’t be changed. Currently this works out at a size for the Persist folder of just over 500 MB, and a total folder size for the whole of /var/db/diagnostics of around 1.1 GB.
Log files are aged in different ways. Those in Persist remain intact until deleted as whole files, but those in the Special folder are progressively thinned (weeded) until a file becomes empty, when that file is finally deleted.
Each tracev3 file of main log entries stored in the Persist folder normally contains around 350,000 log entries in total; as there are usually around 50 such files in that folder at any time, the total accessible log entries are typically about 17.5 million. To those should be added entries stored in the Special and Signposts folders, likely to take that total over 20 million.
This allows you to make a rough estimate of the average rate of new log entries being written to those files. If your logs currently go back 24 hours (a period measured by Mints and XProCheck), then the average rate of writing to them is more than 700,000 entries per hour or 12,000 per minute, for example.
Storage process
Initially, most (if not all) log entries appear to be written into memory, from where most are written to disk storage. Some entries are removed at that stage, and never written to disk. This may be reflected in entries accessible to log browsing: some entries seen just a few seconds or minutes after entering the log are missing when the log is accessed more than an hour later. logd
‘s weeding activities can also start soon after an entry is written to disk, particularly for some of the more expansive entries stored in the Special folder.
Performance
At peak periods, such as early during startup, the rate of writing log entries can exceed 10,000 per second, and higher rates are possible during times of apparent crisis.
I first assessed log write performance over four years ago, using two methods to measure latency between successive log writes. One is based on a tight code loop in my command tool blowhole
:
for i in 0..<count {
os_signpost(type, log: myLog, name: "blowhole", signpostID: mySpid, "blowhole %{public}@", "\(i)")
}
The second is an unrolled loop of the form
os_signpost(.begin, log: self.myLog!, name: "begin1", signpostID: mySpid, "1")
os_signpost(.end, log: self.myLog!, name: "begin1", signpostID: mySpid, "2")
Note that both of these write signposts rather than general log entries, as appropriate for their purpose.
When I first measured the second, unrolled loop, using Whither on a MacBook Pro (2.5 GHz i7), the time gap between successive signposts was just over 580 nanoseconds (Intel Mach ticks). More recently, in Catalina on an iMac Pro (3.2 GHz 8-Core Intel Xeon W), that had fallen to around 385 ns, and the blowhole
loop ran at about 1400 ns per loop.
In Ventura 13.2, figures for the same iMac Pro are similar, with the unrolled loop achieving an average of 387 ns with a minimum of 374 ns, and blowhole
slightly slower than before at an average of 1560 ns. On a Studio M1 Max, the unrolled loop is much faster at an average of 177 ns with a minimum of 125 ns, but blowhole
remains at an average of 1583 ns.
One significant limitation of these results from Apple silicon Macs is the resolution of Mach ‘ticks’ on M-series chips. On Intel Macs, each tick represents 1 nanosecond, but on M-series chips that’s 41.67 ns, and the shortest measured time interval in these tests was just 3 ticks long, hence 125 ns.
Nevertheless, performance of the log system in macOS is extremely swift by any standard, and even faster on Apple silicon. To be able to write consecutive log entries every 2 µs reflects the low overhead in the log system, and its value in timing events of even very short duration. It also explains how, at full flight, the log can write so many entries, and become such a challenge to access.
Controlling log output
Although you can’t disable the log, you can control which entries get written to the log files on disk. If you need to reduce superfluous entries to prolong the period covered by log files, this article explains how to assess the situation and how to go about changing log preferences and this article explains how to use the latest features in Ulbow to do so.