Last Week on My Mac: Catching up with Time Machine

It seemed like a good idea at the time, and at least the time was right even if the idea was flawed. The first beta-release of The Time Machine Mechanic, T2M2, was back in the days of macOS Sierra, on 27 May 2017, nearly seven years ago. Many of us were then victims of a serious bug in the scheduling system that resulted in automatic backups grinding to a halt. As Time Machine itself appeared oblivious to that failure, the only way to investigate it was using the newly Unified log. I reported that bug on 25 February 2017, and it was eventually fixed in High Sierra, exactly seven months later.

As the only utility available to browse the log was the first release of Console, which couldn’t (and still can’t) browse back in time to reveal past entries in the live log, this wasn’t an easy task, and drove me to develop Consolation, first released three months earlier. But the need for a more accessible means of checking automatic backups was sufficiently great to justify a purpose-built app: version 1 of T2M2 was released on 9 June 2017.

Ever since, I have been playing catchup with Time Machine. No sooner do I get it right than the log entries on which it depends are changed.

Like many other services in macOS, Time Machine is in an odd position. It’s not seen as fair game for developers, and the only time I can recall any session in WWDC discussing it was during the release of APFS. For advanced users and system administrators, the command tool tmutil is seen as all that’s required. What Time Machine writes to the public Unified log is deemed private and internal to Apple, and is both undocumented and subject to seemingly arbitrary change.

Yet those log entries are the essence of T2M2: it’s the only way to know what it’s doing, and what isn’t going according to plan. One good illustration of the problems faced is in speed and progress reports, first introduced for Catalina on 19 February 2020.

Slow backing up is probably the most common problem with Time Machine, but discovering what makes a backup slow had been well nigh impossible. During my testing of this new feature, I discovered why backups in Catalina 10.15.3 had become almost impractical: they were trying to copy the hidden .DocumentRevisions-V100 folder containing that volume’s version database. I reported that bug on 20 February 2020, and it was fixed in the betas of Big Sur, and its full release that November. As far as I’m aware, all that was required was to add that folder to the system exclusions list for Time Machine. Considering Time Machine couldn’t restore that folder when it had been backed up, it remains a mystery why it ever wasted so much time trying to copy it in the first place.

Big Sur brought major change: for the first time, backing up to APFS was supported, and there were plenty of modifications required in T2M2 to accommodate that. Those crucial progress reports were still brief and simple, though, such as
Copied 65.87 GB of 245.16 GB, 766126 of 1558140 items (~61.06 MB/s, 166.62 items/s). Last path seen: /Volumes/External3/2020-06-27-150714.inprogress/Macintosh HD – Data/Users/hoakley/OtherDocuments/TMbackups.sparsebundle/bands/58
Finding those in log extracts was straightforward using a search predicate that looked for the text “Copied “, with a trailing space for specificity.

Since then, each new version of macOS has brought further change in the structure and content of Time Machine’s log entries. Backing up to APFS has also sprung new problems, including snapshots that seem to get overlooked and aren’t deleted when they should be, and a few users accumulating hundreds of backups that never get thinned. As those don’t get reported to the user, coverage and role of T2M2 has broadened considerably.

From Monterey onwards, progress reports have become extensive, and are no longer found by looking for “Copied “. Here’s an example from Monterey:
. .
Progress: 1% done, -, – MB/s, avg: 0.00 MB/s, – items/s, avg: 0.00 items/s
FSPhysicalSize:1% (CV:531.7 MB/96.39 GB (D: Zero KB),T:96.39 GB,D:Zero KB(-),LA:Zero KB(-))Y
FSCompletedItems:1% (CV:9114/1257523 (D: 0),T:1257523,D:0(-),LA:0(-))Y
TTCompletedEventPaths:- ()N
Copied: 9137 (l:692.3 MB p:531.7 MB) Propagated: 0 (l:Zero KB p:Zero KB) Propagated (shallow): 0 (l:Zero KB p:Zero KB)
Tracker: FlCp:5926DrCp:3188SmCp:23
Lookups:
Comparisons: Operations:
Backup Projected Stats: 1258524 items (p:96.96 GB)
Sized: l:121.7 MB p:122.9 MB c:1000, Outstanding:0/2, Finished Volumes:0
Current: Zero KB/(l:40.7 MB,p:40.7 MB) – /Volumes/newBackups 1/2022-01-19-121106.inprogress/Data/Library/Application Support/Logic/EXS Factory Samples/Drum Kit Designer Consolidated/Drum Kit Designer/Stereo/SoCal Kit Crash_consolidated.caf

The first line is actually a progress emoticon, which gradually fills with • “BULLET” characters as the backup progresses. Note that “Copied” does appear, but here with a trailing colon before the space, sufficient difference to break a search predicate.

Last week I released a new version of T2M2 intended to cater specifically for all the changes that have taken place recently, and to work much better with Sonoma. Although its Speed feature adopts the format introduced in Monterey, using a search predicate for “Copied ” fails to find these progress entries, but using “Progress: ” seems both reliable and specific. And useless with Big Sur, an issue that I’ll address in the next update.

Amplify that for all the other search terms that T2M2 has to use to generate its general report on Time Machine, and you can see the problems it faces. To get this completely right, each version of macOS requires a different version of T2M2, and that’s before it has even addressed the thorny problem of detecting and reporting errors.

While T2M2 will continue catching up with Time Machine’s log entries, I hope it still helps you check and diagnose problems in Time Machine, at least using some combination of version 1.x and 2.x, depending on which is better for that version of macOS.