The first article in this series explained the principles involved in Time Machine (TM), how it has changed over different versions of macOS, and the tools you need to diagnose its problems. This article looks in more detail at what you should see in the unified log in Sierra and later, and how problems can manifest themselves there.

Sierra

Sierra is quite similar in the log entries to those of El Capitan and earlier, summarised in the diagram above.

Time Machine’s first task in the backup is to determine the destination backup folder, then to work out what needs to be backed up on that occasion. For HFS+ volumes, Time Machine’s backupd examines the hidden FSEvents records stored at the root of each volume, which record the changes made to its files and folders. If it can’t find a ‘proper’ FSEvents record, then it performs a deep traversal of the volume to construct one. Deep traversals can take a long time, and in many cases may take over an hour, leading to cancellation of the next scheduled backup.

Once backupd knows what needs to be backed up, it calculates the disk capacity required. This has to allow for overhead or ‘padding’. This is compared with the free space on the backup destination: if there is room, the backup proceeds, otherwise this throws an error.

backupd then copies changed items to the backup destination. It then makes hard links to all the unchanged files and folders.

With the backup itself complete, backupd turns to maintenance tasks, and identifies which old backups have expired, according to its rules. Those are then deleted in a process which can take longer than making the backup itself. Once that task is done, backupd reports that the backup is complete, which is signalled back to CTS and DAS so that the next automatic backup can be scheduled by DAS.

A typical sequence in the log might read:
47:17.053 com.apple.backupd[7985]: Starting automatic backup
47:17.268 Backing up to /dev/disk3s2: /Volumes/PROMISE PEGASUS/Backups.backupdb
47:18.834 Will copy (304.1 MB) from Macintosh HD
47:18.834 Found 239 files (304.1 MB) needing backup
47:18.863 14.63 GB required (including padding), 3.23 TB available
51:01.273 Copied 360 items (304 MB) from volume Macintosh HD. Linked 9332.
51:08.237 Created new backup: 2016-07-07-075106
51:10.048 Starting post-backup thinning
54:15.363 Deleted /Volumes/PROMISE PEGASUS/Backups.backupdb/Howard’s iMac/2016-07-06-065322 (27.1 MB)
54:15.363 Post-backup thinning complete: 1 expired backups removed
54:19.280 cBackup completed successfully.

When TM can’t find a reliable FSEvents database for a volume, it reports a Deep Traversal on an HFS+ volume thus:
09:44.382003 Forcing deep traversal on source: "Macintosh HD" (device: /dev/disk2 mount: '/' fsUUID: BE50387F-1302-31FB-B567-68F50F8ADE7A eventDBUUID: FDAC9A01-ECB1-4AFA-8F58-B018F81CF569)
09:44.398792 Deep event scan at path:/ reason:must scan subdirs|require scan|
09:44.398917 Running event scan
09:44.399022 periodic consistency scan for '/'
57:54.162626 Finished scan
57:54.244922 Saved event cache at /Volumes/PROMISE PEGASUS/Backups.backupdb/Howard’s iMac/2017-02-18-080944.inProgress/6C87A4AF-8E4C-41C5-B8FE-62BCA79A27F4/.BE50387F-1302-31FB-B567-68F50F8ADE7A.eventdb

When first backups or subsequent runs stall, it’s normally straightforward to identify at which point they have become stuck. If that has occurred during a Deep Traversal, try to leave it running so that it completes the backup, even if this takes several hours. The Deep Traversal has been started because FSEvents is missing or damaged: if you try to start the backup again, then that situation won’t improve, and you’ll still be stuck trying to complete a Deep Traversal scan before a backup can be made.

Sometimes the Deep Traversal results in many identical errors, which identify one or more files which are blocking its completion. It may help then to repair the volume, or to delete the offending file(s) if they aren’t of great importance.

High Sierra and Mojave from APFS

The increased number of steps is reflected by considerably more entries in the log.

backupd is scheduled using the same mechanism, which now isn’t as prone to failure as it was in Sierra. This starts in the normal way, by determining the destination for the backup. Having recognised that it has an APFS volume to back up to that, it then follows a different sequence.

The preparatory sequence identifies and deletes expired local snapshots, which are kept for 24 hours, and you should expect to find a full 24 hours of snapshots at any time.

Once that maintenance is complete, backupd makes a fresh snapshot, which is saved to the backup folder. This is set as the ‘stable’ snapshot, and mounted ready for access. The last snapshot, made an hour earlier during the previous Time Machine backup, is then mounted too as the ‘reference’, and backupd determines which files and folders should be backed up by comparing those two snapshots, as stored in their backup folders.

backupd then checks that there is sufficient free space on the backup destination, and if there is, performs the same process as with HFS+, copying changed items and making hard links to the rest. That is followed by new steps, which save a clone family cache to the new backup folder, and back-up-later caches there too.

The two snapshots are then unmounted, their job complete, and the latest snapshot is marked as the next to be used as the reference snapshot when backupd is next run.

A second local snapshot is then made, which shows the state of the file system on completion of the backup. This appears to be saved to the local snapshot store and not copied to the backup, and is intended for use when the full Time Machine backup isn’t available. It is accessible in the Time Machine app: for the previous 24 hours, for an APFS volume, you should find two backups made every hour instead of one. The first represents that in the backup destination, and the second (a few minutes later) is the local snapshot.

backupd finally performs the same maintenance routines on the backup folder, to remove old expired backups, on completion of which it reports that the backup is complete.

Here is a typical log sequence from Mojave:
37:13.324510 Starting automatic backup
37:13.944141 Backing up to /dev/disk3s2: /Volumes/PROMISE PEGASUS/Backups.backupdb
37:15.303692 Starting age based thinning of Time Machine local snapshots on disk '/'
37:15.306357 Age based thinning deleted Time Machine snapshot 'com.apple.TimeMachine.2018-10-12-074443' on disk '/
37:20.814376 Created Time Machine local snapshot with name 'com.apple.TimeMachine.2018-10-12-093715' on disk '/'
37:20.821185 Declared stable snapshot: com.apple.TimeMachine.2018-10-12-093715
37:21.222744 Mounted stable snapshot: com.apple.TimeMachine.2018-10-12-093715
at path: /Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/Howard’s iMac/2018-10-12-093715/Macintosh HD source: Macintosh HD
37:21.823102 Mounted reference snapshot: com.apple.TimeMachine.2018-10-12-083723
at path: /Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/Howard’s iMac/2018-10-12-083723/Macintosh HD source: Macintosh HD
37:44.916779 Will copy (637.5 MB) from Macintosh HD
37:44.917419 Found 1447 files (637.5 MB) needing backup
37:44.953124 7.97 GB required (including padding), 4.49 TB available
41:12.017287 Copied 1593 items (623.3 MB) from volume Macintosh HD. Linked 19601.
41:12.037146 Saved clone family cache for 'Macintosh HD' at /Volumes/PROMISE PEGASUS/Backups.backupdb/Howard’s iMac/2018-10-12-093721.inProgress/14F6D6F4-4BCA-4EA1-B4F5-67A5B9623254/.BE50387F-1302-31FB-B567-68F50F8ADE7A.clonedb
41:12.688615 Saved back-up-later cache at /Volumes/PROMISE PEGASUS/Backups.backupdb/Howard’s iMac/2018-10-12-093721.inProgress/14F6D6F4-4BCA-4EA1-B4F5-67A5B9623254/.reservations.plist
41:14.014047 Saved back-up-later cache at /Volumes/PROMISE PEGASUS/Backups.backupdb/Howard’s iMac/2018-10-12-093721.inProgress/14F6D6F4-4BCA-4EA1-B4F5-67A5B9623254/.reservations.plist
41:14.259024 Unmounted local snapshot: com.apple.TimeMachine.2018-10-12-093715 at path: /Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/Howard’s iMac/2018-10-12-093715/Macintosh HD source: Macintosh HD
41:14.507748 Unmounted local snapshot: com.apple.TimeMachine.2018-10-12-083723 at path: /Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/Howard’s iMac/2018-10-12-083723/Macintosh HD source: Macintosh HD
41:15.039030 Marked as reference snapshot: com.apple.TimeMachine.2018-10-12-093715
41:15.161260 Completed snapshot: 2018-10-12-094114
41:16.127934 Starting post-backup thinning
42:01.489936 Deleted /Volumes/PROMISE PEGASUS/Backups.backupdb/Howard’s iMac/2018-10-11-090416 (12.2 MB)
42:01.489947 Post-backup thinning complete: 1 expired backups removed
42:01.580128 Backup completed successfully.

This is prone to individual item errors, of which the following are two examples of little or no significance:
Error: (-5000) SrcErr:NO Copying /Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/Howard’s iMac Pro/2019-05-19-234106/Macintosh HD/Users/hoakley/Library/Group Containers/493CVA9A35.com.red-sweater/Library/Application Support/MarsEdit4/App Store Receipts/D0817AD589EB to /Volumes/PROMISE PEGASUS 1/Backups.backupdb/Howard’s iMac Pro/2019-05-19-234106.inProgress/45C94758-152B-4846-9F71-D207A160C892/Macintosh HD/Users/hoakley/Library/Group Containers/493CVA9A35.com.red-sweater/Library/Application Support/MarsEdit4/App Store Receipts

Sandbox: backupd(50377) System Policy: deny(1) forbidden-link-priv /Volumes/PROMISE PEGASUS 1/Backups.backupdb/Howard’s iMac Pro/2019-05-19-223907/Macintosh HD/Applications/MarsEdit.localized/MarsEdit.app/Contents/_MASReceipt/receipt /Volumes/PROMISE PEGASUS 1/Backups.backupdb/Howard’s iMac Pro/2019-05-19-234106.inProgress/45C94758-152B-4846-9F71-D207A160C892/Macintosh HD/Users/hoakley/Library/Group Containers/493CVA9A35.com.red-sweater/Library/Application Support/MarsEdit4/App Store Receipts/D0817AD589EB
Violation: System Policy: deny(1) […]
Process: backupd [50377] […]

Catalina

With a minimum of two, and in most cases three or more, volumes to back up, the sequence in Catalina is considerably more lengthy. The boxed section in the middle is repeated for each of the volumes to be backed up.

Strategies available for determining the files to back up include:

• first backup – all files and folders, other than those in the exclude list, are copied;
• deep scan – a scan is performed of the volume looking at modification dates, which can be very slow on large volumes, but is simplest on small volumes like Recovery;
• FSEvents – the FSEvents database for that volume is used, as is the default for HFS+ volumes;
• snapshot diffing – two snapshots are compared to determine the differences, as was the default for APFS volumes in High Sierra and Mojave.

The first time that the System and Data volumes are backed up, they should use the first backup strategy. The Recovery volume adopts the deep scan strategy on the second and subsequent backups. HFS+ volumes can only use FSEvents or, when that database is missing or damaged, a deep scan. APFS volumes have the greatest flexibility, with FSEvents as the normal first choice, after which snapshot diffing is used instead, with a deep scan as the fallback when all else has failed.

The start of the backup sequence is heralded by
10:56.951016 backupd TimeMachine Starting automatic backup

Following that, macOS looks for a sparsebundle to back up to
10:56.953108 backupd TimeMachine Looking for sparsebundle for host UUIDs '(
"F579E47E-F6C9-5D32-BE1E-66E17E83B339"
)' or MAC addresses '(
88e9fe4e8bca
)' in directory '/Volumes/ExternalSSD2'
Note that this can be identified either by a host UUID, which is usual, or by a MAC address.

The Recovery volume is mounted next
10:57.067409 backupd TimeMachine Mounted recovery volume at /Volumes/Recovery

And backupd announces the backup destination
10:57.067435 backupd TimeMachine Backing up to ExternalSSD2 (/dev/disk2s2): /Volumes/ExternalSSD2

A local ‘stable’ snapshot of each volume is then created, with an entry like
10:58.961719 backupd TimeMachine Created Time Machine local snapshot with name 'com.apple.TimeMachine.2019-11-11-141058.local' on disk '/'
which should be repeated for each volume being backed up.

Previous ‘reference’ and latest ‘stable’ snapshots are then mounted, with entries such as
10:58.978608 backupd TimeMachine Mounted stable snapshot: com.apple.TimeMachine.2019-11-11-141058.local at path: /Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/Howard’s MacBook Pro/2019-11-11-141058/Macintosh HD - Data source: Macintosh HD - Data
10:58.996564 backupd TimeMachine Mounted reference snapshot: com.apple.TimeMachine.2019-11-11-131153.local at path: /Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/Howard’s MacBook Pro/2019-11-11-131153/Macintosh HD - Data source: Macintosh HD - Data
Each stable snapshot is mounted in turn before mounting the reference snapshots.

backupd then enters the sequence which determines the items to be included in the backup, and written out to an event cache file with the extension .eventdb.

For the Recovery volume, backupd determines which method to use to determine what will be backed up, and generates the event database. For a second or subsequent backup, this should be a deep scan strategy, which is reported as follows
10:59.105896 backupd TimeMachine Possible strategies for "Recovery" (device: /dev/disk1s3 mount: '/Volumes/Recovery' fsUUID: 9E45515F-B169-4338-831B-CCE4B5657CC9 eventDBUUID: (null)) (): first backup, deep scan,
10:59.106547 backupd TimeMachine Deep scan required for source: "Recovery" (device: /dev/disk1s3 mount: '/Volumes/Recovery' fsUUID: 9E45515F-B169-4338-831B-CCE4B5657CC9 eventDBUUID: (null))
10:59.107539 backupd TimeMachine Running deep scan - looking for changes after 2019-11-11 13:10:56 +0000
10:59.125428 backupd TimeMachine Trusting source modification times for complete event history.
10:59.127671 backupd TimeMachine Found 0 perfect clone families, 0 partial clone families. Zero KB physical space used by clone files. Zero KB shared space.
10:59.128534 backupd TimeMachine Saved event cache at /Volumes/ExternalSSD2/Backups.backupdb/Howard’s MacBook Pro/2019-11-11-141059.inProgress/75510780-9057-4097-A56E-EB646413C690/.9E45515F-B169-4338-831B-CCE4B5657CC9.eventdb

For the Data volume, it is usual to adopt the FSEvents strategy instead
10:59.130764 backupd TimeMachine Possible strategies for "Macintosh HD - Data" (device: /dev/disk1s1 mount: '/System/Volumes/Data' fsUUID: A86D5F30-2372-44D6-BA86-E92B079DDF56 eventDBUUID: 8B03C842-BB4D-4484-B81C-297A3F6AB325) (): first backup, deep scan, FSEvents, snapshot diffing,
10:59.131520 backupd TimeMachine Using FSEvents for source: "Macintosh HD - Data" (device: /dev/disk1s1 mount: '/System/Volumes/Data' fsUUID: A86D5F30-2372-44D6-BA86-E92B079DDF56 eventDBUUID: 8B03C842-BB4D-4484-B81C-297A3F6AB325)
10:59.133036 backupd TimeMachine Read 342 clone families from /Volumes/ExternalSSD2/Backups.backupdb/Howard’s MacBook Pro/2019-11-11-131207/.A86D5F30-2372-44D6-BA86-E92B079DDF56.clonedb
10:59.142412 backupd TimeMachine Buffering events...
10:59.153898 backupd TimeMachine Buffered 680 events.
10:59.155953 backupd TimeMachine Collected 1 events. Last path seen: 'private/var/log/system.log'
10:59.249625 backupd TimeMachine Trusting source modification times for complete event history.
10:59.249658 backupd TimeMachine Found 0 perfect clone families, 0 partial clone families. Zero KB physical space used by clone files. Zero KB shared space.
10:59.252695 backupd TimeMachine Saved event cache at /Volumes/ExternalSSD2/Backups.backupdb/Howard’s MacBook Pro/2019-11-11-141059.inProgress/75510780-9057-4097-A56E-EB646413C690/.A86D5F30-2372-44D6-BA86-E92B079DDF56.eventdb
This is repeated for the System volume, which should also adopt FSEvents. If either falls back to doing snapshot diffing, suspect that trouble isn’t far away, and when backupd is forced to resort to a deep scan for a normal APFS volume, you know that trouble has struck, and you’ll be waiting a long time, just as with an old-fashioned Deep Traversal on HFS+.

Once all the event caches have been saved, the next step is, for each volume in turn, to calculate the space required. Unless this is the first backup since a system update, both the Recovery and System volumes should be unchanged, and have no files for backup.
10:59.280027 backupd TimeMachine Estimating size of changes for "Recovery" (device: /dev/disk1s3 mount: '/Volumes/Recovery' fsUUID: 9E45515F-B169-4338-831B-CCE4B5657CC9 eventDBUUID: (null))
10:59.282800 backupd TimeMachine (fsk:0,dsk:1,fsz:0,dsz:0)(1/0)
10:59.283917 backupd TimeMachine Sizing by file event iteration for source Recovery completed. Changed content estimate: (bytes: 0 (Zero KB), items: 2)
10:59.285932 backupd TimeMachine Estimated 2 files (Zero KB) need to be backed up from 'Recovery'
If there hasn’t been a system update but there are plenty of files to be backed up from Recovery, something has gone seriously wrong, either with that volume or in backupd. Check back through previous entries for the Recovery volume, to see if (for example) the date of the last backup is incorrect, which might lead to false positives being picked up during the deep scan.

The one volume for which you’d expect there to be plenty of files to be backed up is the Data volume.
10:59.288410 backupd TimeMachine Estimating size of changes for "Macintosh HD - Data" (device: /dev/disk1s1 mount: '/System/Volumes/Data' fsUUID: A86D5F30-2372-44D6-BA86-E92B079DDF56 eventDBUUID: 8B03C842-BB4D-4484-B81C-297A3F6AB325)
10:59.293063 backupd TimeMachine (fsk:0,dsk:1,fsz:0,dsz:0)(3/106)
11:00.282070 backupd TimeMachine Sizing by file event iteration for source Macintosh HD - Data completed. Changed content estimate: (bytes: 31586906 (31.6 MB), items: 208)
11:00.284420 backupd TimeMachine Estimated 208 files (31.6 MB) need to be backed up from 'Macintosh HD - Data'

In contrast, when that is repeated for the System volume, in the absence of a recent system update, this too should draw a blank.
11:00.286609 backupd TimeMachine Estimating size of changes for "Macintosh HD" (device: /dev/disk1s5 mount: '/' fsUUID: D9350CE9-7741-4BEA-B0D0-0A8A7420443D eventDBUUID: 0027C297-BF1E-440C-AB89-E8471634F57A)
11:00.288815 backupd TimeMachine Sizing by file event iteration for source Macintosh HD completed. Changed content estimate: (bytes: 0 (Zero KB), items: 1)
11:00.291145 backupd TimeMachine Estimated 1 files (Zero KB) need to be backed up from 'Macintosh HD'

backupd should then arrive at a grand total number of files and their size for this backup
11:00.292344 backupd TimeMachine Estimated 211 files (31.6 MB) need to be backed up from all sources
Note that in Catalina, this isn’t seen to be compared with free space available, as it was in Mojave and earlier.

backupd then copies the files which are to be backed up
11:00.407950 backupd TimeMachine Copied 1 items (Zero KB) from volume Recovery. Linked 1. Moved 0
11:00.408435 backupd TimeMachine Found 0 perfect clone families, 0 partial clone families. Shared space Zero KB (0 bytes).
11:06.654761 backupd TimeMachine Copied 285 items (31.5 MB) from volume Macintosh HD - Data. Linked 2310. Moved 0
11:06.655632 backupd TimeMachine Found 0 perfect clone families, 0 partial clone families. Shared space Zero KB (0 bytes).
11:06.657546 backupd TimeMachine Saved clone family cache for 'Macintosh HD - Data' at /Volumes/ExternalSSD2/Backups.backupdb/Howard’s MacBook Pro/2019-11-11-141059.inProgress/75510780-9057-4097-A56E-EB646413C690/.A86D5F30-2372-44D6-BA86-E92B079DDF56.clonedb
11:06.949677 backupd TimeMachine Copied 5 items (69 bytes) from volume Macintosh HD. Linked 7. Moved 0
11:06.950550 backupd TimeMachine Found 0 perfect clone families, 0 partial clone families. Shared space Zero KB (0 bytes).

All the local snapshots are unmounted in sequence, with entries such as
11:07.324930 backupd TimeMachine Unmounted local snapshot: com.apple.TimeMachine.2019-11-11-141058.local at path: /Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/Howard’s MacBook Pro/2019-11-11-141058/Recovery source: Recovery

The last snapshots are marked as references ready for the next backup
11:09.740827 backupd TimeMachine Marked as reference snapshot: com.apple.TimeMachine.2019-11-11-141058.local

The final announcements then declares the backup completed, and confirms the mountpoint of the backup, which should match that given at the start
11:09.741046 backupd TimeMachine Completed backup: 2019-11-11-141108
11:09.741366 backupd TimeMachine Mountpoint '/Volumes/ExternalSSD2'is still valid
11:10.211622 backupd TimeMachine Mountpoint '/Volumes/ExternalSSD2'is still valid
11:10.516239 backupd TimeMachine Backup completed successfully.

For backups which have become stuck in progress, most commonly with TM reporting that they are in preparation for a period of many hours, tracing these stages using Consolation is a key step in diagnosis. They are less likely to be revelatory, though, once the first complete set of backups has been made. For that, you’ll need T2M2, which I’ll consider in the next article in this series.

This series is dedicated to James Pond (1943-2013), who really did know everything about Time Machine.