Watching Grand Central Dispatch at Work

Time Machine backups do something no user can do: they run as a Grand Central Dispatch (GCD) scheduled task. As I have explained earlier, this means that they are timed flexibly, so that they are energy-efficient and preserve the responsiveness of the user interface. Utilities which manage Time Machine backups cannot use this mechanism, but have to run those backups using launchd. That makes them more punctual, but loses all the advantages of GCD.

This article is part of my quest to discover how a third party might be able to get the best out of GCD when running scheduled tasks.

I’ll start with something very basic: writing text to a window, and to Sierra’s new log. This is reasonably well documented in Apple’s Energy Efficiency Guide for Mac Apps, although as usual there isn’t a code example.

All that I did was create a simple Cocoa app with a button to run the GCD-controlled activity, which called this function:
private func calculate() {
let activity = NSBackgroundActivityScheduler(identifier: "co.eclecticlight.GCDlaunch.check")
activity.tolerance = 2 * 60
activity.schedule() { (completion: NSBackgroundActivityScheduler.CompletionHandler) in
self.outLabel1.stringValue = "Bingo!"
os_log("Finished GCDlaunch.")

That registers the activity with the given identifier co.eclecticlight.GCDlaunch.check, gives GCD a tolerance period of 2 minutes in which to run the activity, then defines that as changing the text in the window, and writing to Sierra’s log. To turn that into a repeated task, instead of giving a tolerance, you set it to repeat and give it a time interval:
activity.repeats = true
activity.interval = 2 * 60

In practice, such activities should not be run at that frequency, which gives bizarre timing results, but should be every 30 minutes or longer to get the most out of GCD.

When the app is run and the button clicked, this is the sequence of log entries which shows a repeated activity being added to Centralised Task Scheduling (CTS):
20:34:49.798860+0100 ( [] Submitting DASActivity: <_DASActivity: "501:co.eclecticlight.GCDlaunch.check", Maintenance, 60s, [30/04/2017, 20:33:49 - 30/04/2017, 20:35:49], Plugin Required>
20:34:49.798915+0100 ( [] Registered unmanaged XPC Activity: co.eclecticlight.GCDlaunch.check
20:34:49.798941+0100 ( [] co.eclecticlight.GCDlaunch.check: <dictionary: 0x7fc6e85777e0> { count = 7, transaction: 1, voucher = 0x7fc6e8573ed0, contents =
"Repeating" => <bool: 0x7fff9a188aa8>: true
"_SequenceNumber" => <uint64: 0x7fc6e85772b0>: 1
"GracePeriod" => <int64: 0x7fc6e8557990>: 60
"Interval" => <int64: 0x7fc6e8518a30>: 120
"name" => <string: 0x7fc6e8577b40> { length = 32, contents = "co.eclecticlight.GCDlaunch.check" }
"Delay" => <int64: 0x7fc6e85605e0>: 60
"Priority" => <string: 0x7fc6e8577b70> { length = 11, contents = "Maintenance" }

Most of those settings can be adjusted to taste.

When the time comes to run that repeated task, this is the sequence of calls seen in the log:
20:14:22.289795+0100 (DuetActivitySchedulerDaemon) [] Rescoring all 73 activities [<private>]
mark the start of the Duet Activity Scheduler (DAS) re-assessing all the activities in its list. This is followed by details of those activities which it deems can proceed, and those which must not. Among them is GCDlaunch:
20:14:22.290441+0100 (DuetActivitySchedulerDaemon) [] <private>:[
<private> ] sumScores:36.295714, denominator:39.010000, FinalDecision: Can Proceed FinalScore: 0.930421}
20:14:22.290455+0100 (DuetActivitySchedulerDaemon) [] '<private>' CurrentScore: 0.930421, ThresholdScore: 0.346336 DecisionToRun:1

Its score is close to 1, and DAS therefore decides to run the activity, so tells CTS to do so:
20:14:22.292028+0100 ( [] DAS told us to run co.eclecticlight.GCDlaunch.check
20:14:22.292031+0100 (DuetActivityScheduler) [] STARTING: <private>
20:14:22.343927+0100 ( [] evaluating activities
20:14:22.343979+0100 ( [] co.eclecticlight.GCDlaunch.check state change 1 -> 2
20:14:22.343980+0100 ( [] Initiating XPC Activity: co.eclecticlight.GCDlaunch.check
20:14:22.344672+0100 ( [] taking power assertion: co.eclecticlight.GCDlaunch.check: 34400

Although my simple example app does not use lightweight inter-process communication (XPC) explicitly, CTS uses it, and runs the code set out in the completion above, which is
self.outLabel1.stringValue = "Bingo!"
os_log("Finished GCDlaunch.")

This changes the text in the window, and writes that simple message to the log. Once those are done, the activity is marked as being complete, and DAS then rescores the activity and determines not to run it again just yet.

My theory is that, just as it is possible to write to a window and to the log from a completion as here, it should be possible to launch and run a command tool. Unfortunately, trying to do that in the conventional way does not appear to work. I now have to work out why.