Last Week on my Mac: The value of log access

We can be remarkably sensitive to changes in the buildings, appliances, and creatures around us. The hard drives in my RAID, which carry my Time Machine backups, have been slightly noisy from new, chattering away happily when the hourly backup takes place. Expecting those to occur a little after ten past the hour, I was surprised yesterday morning to hear them still busy at around half past eight. A quick glance at the Time Machine item in the menu told me that it was preparing a backup.

I immediately knew something was wrong. I vaguely recalled the last backup starting less than twenty minutes before, and was curious as to why Time Machine should apparently be making another.

Having spent quite a bit of last week working on Consolation, my log browser, I quickly fired that up, and discovered that backups had been occurring correctly at around ten past every hour, the last starting at 07:12 and completing just over a minute later. But at 08:09, Time Machine had started another backup, only to switch to performing a ‘deep event scan’, with which it was still occupied, and which was keeping the RAID busy.

I’ll explain the significance of this event in Time Machine in another article, but without access to my recent log entries, I would never have found out what was going on, or possibly going wrong. It was too late to open Console and see anything which might explain this behaviour, as it was already in progress.

It turns out that deep event scans can be a sign of more sinister problems, not just with Time Machine, but with the drive that is being backed up. In any case, when Time Machine is still preparing a routine backup twenty minutes after it started, that is a good indicator that something serious may be amiss.

I am not sure what Apple, in providing me with just the current emasculated and all-but-useless version of Console, would have expected me to do. This iMac has AppleCare cover, but I can imagine the response had I contacted Apple support: immaculately polite, reassuring, and nugatory. I could perhaps have cancelled our weekly family lunch and trudged over by ferry to Southampton, lugging the whole 27″ iMac, to see if I could get some help at the Genius Bar there.

This is the same as when you detect a subtle change in the behaviour of your car when you are driving it. The sudden onset of rear-end sloppiness in handling, and a one-sided increase in tyre noise, that indicates a deflating back tyre, for example. The wise driver eases off and looks for somewhere to pull over and check, and has a tyre pressure gauge handy just in case.

One reason why Apple may not want us to look at Sierra’s new log is its wealth of detail. Even the most insatiably curious are quickly discouraged by Console, which so quickly becomes overwhelmed by the rate at which new entries appear. At peak time, during startup (which you cannot examine using Console anyway) there can be several hundred log entries made every second.

It isn’t that difficult to realise how to filter your way through the torrent and focus on what is relevant. In my case, I knew that this involved Time Machine and its daemon backupd, which is well within the capabilities of most users. Once I had discovered exactly when Time Machine decided that it needed to perform this deep event scan, I could then browse all log entries over a much briefer period, to look for errors which might have led to that taking place.

Of course, being able to browse the log purposefully deepens insight into what goes on within macOS – something that Apple may not wish us to do. Last week I explained how Grand Central Dispatch (GCD) was involved in launching automatic Time Machine backups. Apple has been promising us a manual on how GCD works for several years now, but has still failed to give detail on how macOS uses it. Its developer documentation explains how third-party developers can use GCD with their apps, but that falls well short of describing its internals, which are used more directly by services such as Time Machine.

Giving us a near-useless version of Console is myopic and unsupportive. It leaves users at all levels unable to answer simple questions, such as why is that backup taking so long. It blocks us from detecting and diagnosing problems in their early stages, before we have incurred data loss, or even hardware damage. Apple must demonstrate its respect for the needs of users, and deliver a fully-functional log browser.