How Time Machine backups are launched in Sierra

When macOS Sierra 10.12.3 launches a Time Machine backup, this is not done simply as a timed task using launchd. These days it involves a complex network of services which operate to minimise the impact that backup has on other activities, to optimise use of your Mac’s available resources, such as free CPU cores, and to minimise power consumption. It is orchestrated by Grand Central Dispatch (GCD).

The first sign that a backup is going to be started is when Duet Activity Scheduler (DAS) runs one of its periodic re-assessments of tasks and their priorities. This uses a scoring system to determine which of the activities on its list should be run next, and the log entries might run thus:
08:09:41.440077 125 DuetHeuristic-BM: (DuetActivitySchedulerDaemon) [com.apple.duetactivityscheduler.default] Rescoring all 73 activities [X]
08:09:41.440218 125 DuetHeuristic-BM: (DuetActivitySchedulerDaemon) [com.apple.duetactivityscheduler.scoring] X:[ X ] sumScores:35.528519, denominator:39.010000, FinalDecision: Can Proceed FinalScore: 0.910754}
08:09:41.440223 125 DuetHeuristic-BM: (DuetActivitySchedulerDaemon) [com.apple.duetactivityscheduler.scoring] 'X' CurrentScore: 0.910754, ThresholdScore: 0.646465 DecisionToRun:1
08:09:41.440335 125 DuetHeuristic-BM: (DuetActivitySchedulerDaemon) [com.apple.duetactivityscheduler.scoring] X:[ X ] sumScores:30.528519, denominator:34.010000, FinalDecision: Must Not Proceed FinalScore: 0.000000}
08:09:41.440345 125 DuetHeuristic-BM: (DuetActivitySchedulerDaemon) [com.apple.duetactivityscheduler.lifecycle] Running activities : X
08:09:41.440500 125 DuetHeuristic-BM: (DuetActivitySchedulerDaemon) [com.apple.duetactivityscheduler.default] Arming timer for activity X
08:09:41.440532 67 UserEventAgent: (DuetActivityScheduler) [com.apple.duetactivityscheduler.client] STARTING: X

(In these and subsequent log excerpts, I have edited entries to show the time, process number, process name, subsystem, and the message. Content marked as <private> has been replaced by X as it is non-contributory. If you want to see the full log entries, please contact me.)

Once DAS has decided to start a backup, this is signalled by the Centralised Task Scheduling (CTS) service using XPC (lightweight interprocess communication), and the backupd-auto daemon is started:
08:09:41.440541 67 UserEventAgent: (com.apple.cts) [com.apple.xpc.activity.All] DAS told us to run com.apple.backupd-auto
08:09:41.440747 125 DuetHeuristic-BM: (DuetActivitySchedulerDaemon) [com.apple.duetactivityscheduler.default] Setting timer (waking=1) between X and X
08:09:41.532491 67 UserEventAgent: (com.apple.cts) [com.apple.xpc.activity.All] evaluating activities
08:09:41.532562 67 UserEventAgent: (com.apple.cts) [com.apple.xpc.activity.All] com.apple.backupd-auto state change 1 -> 2
08:09:41.532566 67 UserEventAgent: (com.apple.cts) [com.apple.xpc.activity.All] Initiating XPC Activity: com.apple.backupd-auto
08:09:41.533057 67 UserEventAgent: (com.apple.cts) [com.apple.xpc.activity.All] taking power assertion: com.apple.backupd-auto: 41883

When CTS is told to run backupd-auto, it first checks when it was last run. If it is being asked to initiate a backup within ten minutes of the last, it will abort the instruction from DAS; otherwise it will proceed with running backupd-auto. For some tasks, CTS reports whether the instruction from DAS is early or late relative to the scheduled time, indicating that it is CTS which monitors performance in relation to schedules.

Time Machine’s backup system consists of three main processes: backupd-helper, a service which is left running in the background at all times, backupd-auto, which is only run periodically to start a backup, and backupd itself, which only runs when making a periodic backup and then does the heavy lifting.

backupd is installed as a LaunchDaemon in /System/Library, by the Property List com.apple.backupd.plist, and backupd-auto and backupd-helper in a separate file named com.apple.backupd-auto.plist in the same folder.

Oddly, the first call by backupd, once it has been started, is to Siri; I have no idea why that should be, but it is consistent! backupd then prepares the resources that it needs to run, fetching the preferences which determine which volumes and folders it should include and exclude, and opening its three logging subsystems, TMLogError, TMLogInfo, and TMLogDebug:
08:10:11.555700 90818 backupd: (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:10:11.557357 90818 backupd: (CoreFoundation) Loading Preferences From System CFPrefsD For Search List
08:10:11.559498 90818 backupd: (CoreFoundation) Loading Preferences From System CFPrefsD For Search List
08:10:11.646073 90818 backupd: (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:10:11.646123 90818 backupd: (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:10:11.646166 90818 backupd: (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

Everything is now set, so backupd starts making the backup. It loads further preferences, works out the destination store to which the backup will be saved, and then (in this case) encounters a minor error:
08:10:11.646414 90818 backupd: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Starting automatic backup
08:10:11.700446 90818 backupd: (SystemConfiguration) accessing SCDynamicStore
08:10:11.726528 90818 backupd: (CoreFoundation) Loading Preferences From System CFPrefsD For Search List
08:10:12.028152 90818 backupd: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Backing up to /dev/disk3s2: /Volumes/PROMISE PEGASUS/Backups.backupdb
08:10:12.700578 90818 backupd: (CoreFoundation) Loading Preferences From System CFPrefsD For Search List
08:10:13.788227 67 UserEventAgent: (TimeMachine) [com.apple.TimeMachine.TMLogError] Failed to send message because the port couldn't be created.

This last error either relates to the animation of the menubar icon to indicate the backup is in progress, or to a logging issue, but happens here in every backup. I think that it can be safely ignored.

backupd then works out the amount of changed files which need to be copied to the backup, estimates the space required, and for the first time starts to involve iCloud:
08:10:17.559819 90818 backupd: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Will copy (215.8 MB) from Macintosh HD
08:10:17.561369 90818 backupd: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Found 2053 files (215.8 MB) needing backup
08:10:17.602892 90818 backupd: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] 15.1 GB required (including padding), 3 TB available
08:10:21.035643 90818 backupd: (libsystem_trace.dylib) subsystem: com.apple.clouddocs, category: default, enable_level: 0, persist_level: 0, default_ttl: 14, info_ttl: 0, debug_ttl: 0, generate_symptoms: 0, enable_oversize: 0, privacy_setting: 0, enable_private_data: 0

This has now entered the backup phase, in which backupd periodically checks preferences, then makes calls to arbitrate access to files, as it works through its backup:
08:10:21.036375 90818 backupd: (CoreFoundation) Loading Preferences From System CFPrefsD For Search List
08:10:21.037543 90818 backupd: (Foundation) [com.apple.foundation.filecoordination.claims] Read (Subarbitration) options: 1 -- URL: -- purposeID: com.apple.desktopservices.copyengine
08:10:21.038243 432 filecoordinationd: (Foundation) [com.apple.foundation.filecoordination.claims] Received claim
08:10:21.038309 432 filecoordinationd: (Foundation) [com.apple.foundation.filecoordination.claims] Subarbitration claim EBC983B2-9A19-43F3-BFDE-2179525ACA50 granted in server
08:10:21.040319 90818 backupd: (Foundation) [com.apple.foundation.filecoordination.claims] Starting subarbitration for 1 URLs
08:10:21.040449 432 filecoordinationd: (Foundation) [com.apple.foundation.filecoordination.claims] Subarbitration claim EBC983B2-9A19-43F3-BFDE-2179525ACA50 invoked in server
08:10:21.040535 90818 backupd: (Foundation) [com.apple.foundation.filecoordination.claims] Subarbitration claim EBC983B2-9A19-43F3-BFDE-2179525ACA50 granted in client
08:10:21.040537 90818 backupd: (Foundation) [com.apple.foundation.filecoordination.claims] Subarbitration claim EBC983B2-9A19-43F3-BFDE-2179525ACA50 invoked in client
08:10:22.943657 90818 backupd: (libsystem_trace.dylib) subsystem: com.apple.libsqlite3, category: logging, enable_level: 0, persist_level: 0, default_ttl: 0, info_ttl: 0, debug_ttl: 0, generate_symptoms: 0, enable_oversize: 1, privacy_setting: 2, enable_private_data: 0

During the backup, there are extensive exchanges concerning iCloud files, confirming backupd‘s role in ensuring that iCloud documents are properly backed up. Eventually, the backup is complete, and preferences are updated:
08:18:16.569401 90818 backupd: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Copied 2143 items (215.9 MB) from volume Macintosh HD. Linked 18120.
08:18:22.213741 90818 backupd: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Created new backup: 2017-02-12-081821
08:18:22.248170 90818 backupd: (CoreFoundation) Sending Updated Preferences to System CFPrefsD
08:18:22.254704 67 UserEventAgent: (CoreFoundation) Loading Preferences From System CFPrefsD For Search List

After some more work with preferences, Time Machine housekeeping is started, which ensures the backup disk is optimally used, and any expired backups are removed:
08:18:22.961416 90818 backupd: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Starting post-backup thinning
and so on.

The launching of periodic backups is thus a complex chain of events. Compare how launchd handles a simple periodic task, running my blowhole tool to make an entry in the logs:
08:18:26.203721 90882 blowhole: [co.eclecticlight.blowhole.general] Blowhole snorted!

That is all that gets written into the logs: in this case, there is no involvement of GCD, scoring lists, XPC, or anything as sophisticated. And that is why Time Machine backups run roughly every hour, while simple hourly scheduled tasks are run almost exactly every hour.

Log extracts were captured using Consolation, running on an iMac17,1 under macOS Sierra 10.12.3. No processes were harmed during the making of this article.