Last Week on my Mac: changing diagnostics

I have always found the bridge of a ship a fascinating place. When I was fortunate enough to work on board a British frigate on an Armilla Patrol in the Persian Gulf in early 1987, I spent a lot of time on the ship’s bridge. One of the most important routines there is maintaining the ship’s log: it is there that you will see every change in course and speed, and other events, recorded in careful detail.

Ships’ logs then form intricately-detailed historical records. Sometimes they can lead to personal disaster: when a ship runs aground, a well-kept log makes it crystal clear what happened, and often who and why.

Unix-like operating systems invariably keep many different logs too; they enable advanced users, system administrators, and developers to observe what has happened in the recent past. These can be specific to a service, such as a web server, or general to the operating system.

Trying to run or administer an operating system and its services without logs is incredibly difficult, a bit like trying to live without even the most momentary of memory. When something does go wrong, you have no idea what happened. The only way to investigate a problem is to try reproducing the error or failure – not something that you’d want to do with a ship, nor many computer faults.

The standard logs in OS X have been widely and heavily used in the past. Software developers rely on them, but also have tailor-made tools for debugging. Users and system administrators have relied on their Mac’s logs to diagnose and address a wide range of problems, such as startup issues, wobbly extensions, apps which unexpectedly quit, kernel panics, freezing when being awakened from sleep, and checking that backups have been completed without errors. Most of these are very difficult to investigate in any other way.

Traditional logs, kept in disk files using text format, are inefficient in every respect. They occupy too much space, contain unstructured information, impose significant overhead on every process which writes to them, and have become cluttered to the point of being almost unusable.

Sierra brings a new compressed binary format for logs, .tracev3, which are now tucked away in the hidden folder /var/db/diagnostics. This logging system typically stores 30-40 MB of fresh logs each day, allowing it to keep more than three days of detailed historical data. It also stores smaller logs containing only faults and errors going back over the last ten days or so. The detail collected in these logs is astonishing and its quantity overwhelming. During the first minute following the starting up of your Mac, there are likely to be more than 70,000 log entries – and that is when everything goes to plan.

Apple has even taken steps to protect the privacy of data which might otherwise appear in these logs, an issue which has long been ignored in the standard Unix approach. As this new logging system is standard across all Apple’s operating systems including iOS, it is an important part of the privacy-in-depth which Apple is championing.

Every Sierra, iOS, watchOS, and tvOS user benefits from these new logs before anyone has even browsed them, because of their reduction in overhead on every process running, from the kernel and its extensions up to applications. Writing an entry in the old logs required the process to laboriously format a text string containing the information, and write it out to the file on disk. Now processes simply pass the data to a system routine, which hands it to a compressor, then into a buffer held in memory. From there, the logging system can store entries as and when it needs.

In system software terms, what Apple has done to its logs is not just remove the headphone socket, but almost as big a leap as replacing those beautiful old ships’ logs crafted in copperplate.

Perhaps, in the wake of this huge leap forward, we should have expected that the tools for accessing these wonderful new logs are lagging. The biggest disadvantage with storing all this data in compressed binary files is that – for the moment, at least – the only tools which can unlock this information are those provided by Apple. And they fall well short of giving us with the access which we had when using the old version of Console.

Currently, doing anything practical with Sierra’s new logs is crude and cumbersome at best, like having to mine a huge database with just a handful of basic SQL commands. The rest of the Sierra engineering team has not helped either, in that many of the log entries made by other parts of Sierra do not yet make full use of the new logging system’s features (such as designating a ‘subsystem’). This is exacerbated by the introduction of the new log system in a major release of macOS – just the time when a lot of Mac users are going to have to deal with system and app problems.

The comparison with Apple’s controversial removal of the headphone socket from its latest iPhones is an interesting one. Far from making that change and then announcing that it would have some suitable supporting products sometime later, Apple launched the new iPhones with (far from bargain) Bluetooth earphones, which must have required considerably more development and engineering effort than a decent tool for accessing historical log data. Yet Apple was quite happy to ship macOS Sierra without the latter.

Looking now at Sierra, its two most important features are actually those buried deepest inside: its new kernel, which seems far more robust than El Capitan’s, and the new logging system. I wonder how long it will take Linux and Windows to switch from copperplate to compressed binary?