One of the commonest serious problems with Time Machine, particularly in macOS 10.15 Catalina, is that backups, particularly the first full backup, never complete, or take days to do so. As I’ll explain in more detail here tomorrow, I’ve just been struck down by this problem, so this article details how to diagnose it.

In my case, it affects the first full automatic or manual backup being made to a new backup folder. It’s completely reproducible: I’ve tried starting this from scratch on at least six occasions, using various changes, and it happens every time, and at exactly the same point during the attempt to back up. My first backup is large, over 1.2 TB, and is being made in 10.15.3 to an empty 6 TB SSD which is connected by Thunderbolt 3 (details follow tomorrow). So there’s no excuse over speed or free space on the backup volume.

Every time that I try to do this, the backup runs very briskly until exactly 215.90 GB have been backed up, then almost stops. When I write almost, I mean that it slows to the point where completion would then take days, or possibly even weeks. There are no errors reported, and T2M2 simply shows that the backup is still in progress. Inspect the log using Console (if you must) and there aren’t any telltale error messages being thrown into the log. The backup just grinds to a near-halt all of a sudden.

The only course of action is to cancel the backup in the Time Machine pane, turn off automatic backups, trash the partial backup, and use a third party product such as Carbon Copy Cloner, which of course clones everything without trouble or error.

The best way to see this is using the latest version of my free log browser Ulbow, with its chart feature. To do this, you’ll need to know of a recent attempt to make a backup which ran into problems, and is still in your log. If you don’t have one, you should know now just how to reproduce it. Once the backup slows down to a crawl, give it a few minutes longer, then cancel it.

Open Ulbow and ensure that you’ve enabled (ticked) the Limit entries shown item in its View menu. Set up a new document window to capture TimeMachineFull as the Predicate (that’s one of the custom predicates supplied with Ulbow). Set the Period to cover the whole of that backup attempt, in my case 25 minutes, then click on the Get log button and wait for Ulbow to display the entries.

In the Window menu use the Open Chart command to show the frequency of All log entries over the period. You should then see something like this.

There’s a flurry of log entries at the start of the backup, as Time Machine works out where to save the backup, makes snapshots, and works out what it needs to back up. After a brief pause, entries continue at a steadier rate until they suddenly drop off, with just the occasional entry after that.

This is shown even more clearly if you switch the Show menu in the chart view to com.apple.distnoted. This is the distributed notification server, which is here reporting every second or so the progress of backing up. Those log entries contain message fields similar to
register name: com.apple.backup.prefschanged object: com.apple.backupd token: f4ec8 pid: 437

Every so often, you’ll see a progress report by com.apple.TimeMachine with a message similar to
Copied 142.87 GB of 1.22 TB, 56390 of 9583508 items (~244.24 MB/s, 52.77 items/s). Last path seen: /Volumes/ThunderBayBackup/Backups.backupdb/Howard’s iMac Pro/2020-02-05-193600.inProgress/419FA367-F20C-4BD5-8CB1-28F2DCA8E610/External1/Pictures/Photos/RawHS10Pics/110123/DSCF1443.RAF
Note the transfer speed quoted in these, here ~244.24 MB/s which looks promising. But once the backup becomes painfully slow, messages from com.apple.distnoted become extremely infrequent, and progress reports look more like
Copied 215.9 GB of 1.22 TB, 78445 of 9583508 items (~0.00 MB/s, 0.24 items/s). Last path seen: /Volumes/ThunderBayBackup/Backups.backupdb/Howard’s iMac Pro/2020-02-05-193600.inProgress/419FA367-F20C-4BD5-8CB1-28F2DCA8E610/External1/.DocumentRevisions-V100/AllUIDs/32/com.apple.documentVersions
with a transfer speed of ~0.00 MB/s. You’ll be waiting until hell freezes over!

You can then use Ulbow to explore what happened when messages from com.apple.distnoted suddenly became so infrequent. I’ve looked through three different events, which all appear almost identical in terms of log entries, but none of which provides any clue as to why the transfer rate suddenly plummets in this way. I can only presume that this is a bug in Time Machine itself, as other apps like Carbon Copy Cloner don’t have any similar problem.

I’d be very interested to know if anyone else discovers the same problems, which account for their very poor or failed backups.