hoakley Macs, Technology

Troubleshooting Time Machine: stuck preparing backup, and the deep event scan

System

macOS Sierra 10.12.x. The same problem can occur in previous releases of OS X, although it may be more likely to be sinister there, and diagnosis is easier because Console gives full log access.

Symptoms

Scheduled Time Machine backups appear to have been running normally, taking a few minutes to complete every hour. A routine backup then starts, but even 10 or 20 minutes later is still in progress. Checking Time Machine shows that it is still ‘preparing backup’.

Diagnosis

The only way to tell the cause of this apparent problem is to open Sierra’s log using Consolation or the log show command in Terminal, and filter entries using the predicate
subsystem == "com.apple.TimeMachine"
or
processImagePath CONTAINS[c] "backup"

The first of these is Consolation’s default setting for Time Machine, as set using the top radio button, making this particularly easy to perform.

The diagnostic log message reads something close to
Forcing deep traversal on source:
followed by the name of the volume being backed up, its Unix device name, where it is mounted, and the UUIDs for its filesystem and the event. This is then normally followed by the log message
Deep event scan at path:/ reason:must scan subdirs|require scan|
or similar. The reason given here should reveal useful clues as to the trigger for the scan.

There are other causes for Time Machine to become stuck in the ‘preparing backup’ phase, which should be evident from log entries.

Explanation

When Time Machine prepares to back up, it examines the FSEvents (File System Events) database, stored in the hidden folder .fseventsd on the volume being backed up, to check which files have been changed since the last backup was prepared. If there are any problems detected with that database, Time Machine cannot use it to determine what it should back up. Its fallback is then to perform a full comparison between the current state of the volume to be backed up, against the last backup which it made – that is a ‘deep traversal’ or ‘deep event scan’ of the volume.

According to the late James Pond, reasons for such issues with the FSEvents database include:

  • the volume has not been backed up before
  • after starting up from a different macOS volume (usually)
  • after a full restore
  • after hard drive or major hardware repair
  • following major changes to the list of exclusions for backups
  • sometimes after major changes to a volume such as a macOS upgrade
  • following a forced or ‘improper’ shutdown, power loss, etc.
  • after an ‘improper’ shutdown or disconnection of the backup drive
  • after a failed or cancelled backup
  • a long time (days) has elapsed since the last backup.

In most of these cases, the reason given for the deep event scan should give clues as to one of those causes.

Actions

All you can do is let the backup complete, then check to see whether it completed without errors. It is vital not to interrupt the deep event scan and subsequent backup, as that will only force Time Machine to perform them again when it is next able to.

Rarely, Time Machine will get stuck and continue performing deep event scans for each scheduled backup. If that occurs, it is vital to eliminate the above causes, and to ensure that there are no issues with the FSEvents database stored in .fseventsd.

Log sequence

Entries shown are from 10.12.3, using Consolation, and give the timestamp, process, and message.

1. Initiation of the deep event scan
This should occur at the start of a normal backup, such as:
08:09:37.846721 backupd[90581]: (libsystem_trace.dylib) subsystem: com.apple.siri, category: Intents, enable_level: 1, persist_level: 1, default_ttl: 0, info_ttl: 0, debug_ttl: 0, generate_symptoms: 0, enable_oversize: 0, privacy_setting: 0, enable_private_data: 0
08:09:37.848372 backupd[90581]: (backupd) Created Activity ID: 0x800000000013c1a0, Description: Loading Preferences From System CFPrefsD For Search List
08:09:37.850112 backupd[90581]: (backupd) Created Activity ID: 0x800000000013c1a1, Description: Loading Preferences From System CFPrefsD For Search List
08:09:37.855970 backupd[90581]: (libsystem_trace.dylib) subsystem: com.apple.TimeMachine, category: TMLogError, enable_level: 3, persist_level: 2, default_ttl: 0, info_ttl: 0, debug_ttl: 0, generate_symptoms: 0, enable_oversize: 1, privacy_setting: 0, enable_private_data: 0
08:09:37.856013 backupd[90581]: (libsystem_trace.dylib) subsystem: com.apple.TimeMachine, category: TMLogInfo, enable_level: 3, persist_level: 2, default_ttl: 0, info_ttl: 0, debug_ttl: 0, generate_symptoms: 0, enable_oversize: 1, privacy_setting: 0, enable_private_data: 0
08:09:37.856064 backupd[90581]: (libsystem_trace.dylib) subsystem: com.apple.TimeMachine, category: TMLogDebug, enable_level: 3, persist_level: 3, default_ttl: 0, info_ttl: 0, debug_ttl: 0, generate_symptoms: 0, enable_oversize: 1, privacy_setting: 0, enable_private_data: 0
08:09:37.856479 backupd[90581]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Starting automatic backup
08:09:37.921123 backupd[90581]: (backupd) Created Activity ID: 0x800000000013c1a2, Description: accessing SCDynamicStore
08:09:37.923436 backupd[90581]: (backupd) Created Activity ID: 0x800000000013c1a3, Description: Loading Preferences From System CFPrefsD For Search List
08:09:37.986942 backupd[90581]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Backing up to /dev/disk3s2: /Volumes/PROMISE PEGASUS/Backups.backupdb
08:09:38.520249 backupd[90581]: (backupd) Created Activity ID: 0x800000000013c1a4, Description: Loading Preferences From System CFPrefsD For Search List
08:09:44.196760 mtmd[90582]: (libsystem_trace.dylib) subsystem: com.apple.siri, category: Intents, enable_level: 1, persist_level: 1, default_ttl: 0, info_ttl: 0, debug_ttl: 0, generate_symptoms: 0, enable_oversize: 0, privacy_setting: 0, enable_private_data: 0
08:09:44.198627 mtmd[90582]: (mtmd) Created Activity ID: 0x800000000013c1b0, Description: Loading Preferences From System CFPrefsD For Search List
08:09:44.201330 mtmd[90582]: (mtmd) Created Activity ID: 0x800000000013c1b1, Description: Loading Preferences From System CFPrefsD For Search List
08:09:44.382003 backupd[90581]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Forcing deep traversal on source: "Macintosh HD" (device: /dev/disk2 mount: '/' fsUUID: BE50387F-1302-31FB-B567-68F50F8ADE7A eventDBUUID: FDAC9A01-ECB1-4AFA-8F58-B018F81CF569)
08:09:44.398792 backupd[90581]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Deep event scan at path:/ reason:must scan subdirs|require scan|
08:09:44.398917 backupd[90581]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Running event scan
08:09:44.399022 backupd[90581]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] periodic consistency scan for '/'

The last log entry here may indicate that this is a routine deep event scan, perhaps initiated to ensure the integrity of backups. As Time Machine internals are undocumented, we cannot know.

2. During the scan
You may see entries such as:
08:13:39.917894 TMCacheDelete[392]: (CacheDelete) [com.apple.cache_delete.client] listener: <private>
08:13:39.917897 TMCacheDelete[392]: (CacheDelete) [com.apple.cache_delete.client] Skipping entitlement check...
08:13:39.920173 TMCacheDelete[392]: (CacheDelete) [com.apple.cache_delete.client] newConnection invalidated

3. Scan completion
Once the scan has finished, you should see the event database saved, and a normal backup performed:
08:57:54.162626 backupd[90581]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Finished scan
08:57:54.244922 backupd[90581]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] 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
08:58:00.201375 backupd[90581]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Will copy (590.8 MB) from Macintosh HD
08:58:00.222696 backupd[90581]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Found 979 files (590.8 MB) needing backup
08:58:05.505432 backupd[90581]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] 15.52 GB required (including padding), 3 TB available
09:03:42.424224 backupd[90581]: (TimeMachine) [com.apple.TimeMachine.TMLogError] Error: (-8084) SrcErr:YES Copying /Users/hoakley/Library/Safari/RecentlyClosedTabs.plist to (null)
09:04:12.024069 backupd[90581]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Copied 1448 items (591.3 MB) from volume Macintosh HD. Linked 13572.
09:04:19.002292 backupd[90581]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Created new backup: 2017-02-18-090418
09:04:19.040208 UserEventAgent[67]: (TimeMachine) [com.apple.TimeMachine.TMLogError] Failed to send message because the port couldn't be created.
09:04:19.703165 backupd[90581]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Starting post-backup thinning
09:07:10.081664 backupd[90581]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Deleted /Volumes/PROMISE PEGASUS/Backups.backupdb/Howard’s iMac/2017-02-17-081136 (52.8 MB)
09:08:39.410998 backupd[90581]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Deleted /Volumes/PROMISE PEGASUS/Backups.backupdb/Howard’s iMac/2017-02-17-071432 (47.3 MB)
09:08:39.411013 backupd[90581]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Post-backup thinning complete: 2 expired backups removed
09:08:44.227364 UserEventAgent[67]: (TimeMachine) [com.apple.TimeMachine.TMLogError] Failed to send message because the port couldn't be created.
09:08:44.343872 backupd[90581]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Backup completed successfully.

In this case, there was one error reported which concerns an unimportant Safari folder, and the backup is still reported as being successful.

You may then see the next automatic backup aborted, if it was to occur too soon after completion of the last one:
09:08:44.407762 backupd-helper[258]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Not starting scheduled Time Machine backup: Less than 10 minutes since last backup