When something goes wrong with your Mac, it is extremely frustrating to know that all the clues are there, somewhere, but you can’t find or interpret them. Earlier this year, I had exactly this problem with Time Machine backups. I – and many others – discovered that what should have been regular hourly backups became irregular when your Mac was left running for a week or so. Mac users are still stumbling across this bug, which Apple never fixed in macOS Sierra.

Although I spent a long time using my log browser Consolation to try to identify the cause, it was hard work, and I had to keep waiting for the problem to recur before I could dive into the log and try to understand what was going on. Sierra’s new unified log is like that: you’re so overwhelmed with log entries that it is often easiest just to give up and try something else.

If only I had had a tool like my new version of Woodpile. Allow me to demonstrate.

This version has two major new features: you can select and analyse any tracev3 log file which is included in the logarchive, and you can add custom processes. I’m going to use both of these here.

Unless things have gone drastically wrong with Time Machine, it makes very few log entries, just a dozen or so every hour. Looking for it in the log load analysis provided by logd is thus a waste of time, particularly when what we’re most interested in is its silence. So I added the process com.apple.TimeMachine to the list of processes, by typing it into the Add process box and pressing the Enter key. I then selected that in the Process popup menu, and started to work my way down through the list of log files in my logarchive. I only got a few down from the top before I found the first ominous gap.

You can see erratic bursts of log entries for Time Machine here, rather than its regular hourly cycle. The gap here happened in the small hours of 25 September. My logarchive was made from my iMac’s live log on 11 October.

I next looked at other processes which showed similar gaps in the same log file – easily done by opening another window on the same logarchive, and working through different items in the Process popup menu with the same Log file setting. Without even having to try any custom process names, I struck gold with DuetHeuristic-BM, which includes log entries for the undocumented DuetActivityScheduler system, DAS, which schedules and dispatches many activities for macOS.

Its silence matches perfectly the gap in backups, and is followed by a spike in log entries.

I also added a process to look at the other part of this scheduling and dispatching system, CTS, whose log entries appear under com.apple.xpc.activity, for the same log file, in a third window on the same logarchive.

This shows a slightly different pattern: although its normal log activity is interrupted, it doesn’t go completely silent when DAS and backups do. This is because CTS also dispatches other activities which do not come through DAS. So the problem looks to be happening in DAS rather than CTS.

To confirm that, and see what happens at the end of the long silence, I go back to the window with DAS charted, and zoom in on its first bar of activity after the silence, with the Command key held down as I click on the bar. This not only zooms in, but fetches the log excerpt covering that period.

I can now see the odd messages being entered into the log at this time by DAS, referring to triggers, and so on. I could easily compare these entries with a section of more normal DAS entries from before the long silence.

In a couple of minutes, I have done what it previously took me many days to achieve.

This new version of Woodpile is available here: woodpile10b1
and in Downloads above.

I hope you find it even more useful than the last.