One of Apple’s touchstones for macOS Mojave and iOS 10.12 is performance. Don’t take my word for it: take Apple’s. The word was used sixteen times in the Keynote at WWDC 2018, and no less than 37 times in the State of the Union address.

Craig Federighi, SVP of Software Engineering, said: “for iOS 12, we are doubling down on performance”. Sebastian Marineau-Mes, VP of Software, introduced Mojave’s new Signposts saying “And of course, making your app run fast is critical. And for that, we have a number of performance tools at your disposal.”

The biggest single problem in measuring performance is that any instrument which measures performance also alters it. This is one of the most important general results from quantum mechanics, and can never be ignored. The unified log in general and Signposts in particular may be convenient to use: as was said later in the State of the Union, “So with just a log statement, a couple of Signposts, you could see I can start to get some really great insight into the performance of my app.” But do you? Just what is the overhead of using the log and Signposts?

A similar question comes up regularly when people ask me about the unified log. What is the performance impact of all these processes in macOS incessantly chattering into the log? When your Mac starts up, and log messages peak at more than 10,000 per minute, doesn’t that slow your Mac down and clog it up?

What brought me to look at these issues was the strange bug which I have stumbled across in the writing of Signposts from Xcode 10ß5 and 6. Although it struck Blowhole, my command tool which writes ordinary log, Pseudo-Signpost, and Mojave Signpost entries, my Signpost-testing app Whither is unaffected.

The difference is likely to rest in the interface between my code and macOS: while Blowhole’s os_signpost() function calls should be handled by library code linked into the command tool, Whither’s are most probably handled through one of the dylibs packaged in the app. This set me wondering whether using a dylib might impose additional overhead, so I designed a small test.

My idea was to measure the time the apps took between calls to os_signpost() and os_log() when running within a tight loop. In Blowhole running under Mojave, this would be
for i in 0..<count {
os_signpost(type, log: myLog, name: "blowhole", signpostID: mySpid, "blowhole %{public}@", "\(i)")
}
for example, with something very similar in Whither. That code writes a Signpost of a given type and Signpost ID, containing the eventMessage of the loop counter, just the sort of thing that you might do when measuring performance with a Signpost. I will be supplying updated versions of Blowhole, Whither, and my Signpost Kit which help you conduct your own performance tests.

In macOS Sierra, looking at similar calls to write to the log (as there is no Signpost support), the time interval between the first and second calls is the longest, at around 40 microseconds. As the loop repeats, that period drops rapidly to settle at 1 microsecond (0.000001 of a second).

Written as a full ‘Pseudo-Signpost’ with some additional text in the eventMessage field, the time interval between first and second calls falls to about 5 microseconds, then levels out at around 1-2 microseconds, whether performed in a background or the main process. If the calls in a full app are made through a dylib, that has no observable effect, when compared with a simple command tool.

Using the command tool, Mojave’s Signposts – and remember that this is still a beta-release which almost invariably will be slower than release versions – are very slightly slower than its log entries. The period between the first and second Signposts is 30 microseconds, and quickly settles to 2-3 microseconds, compared with regular log entries at 22 microseconds settling to 1 microsecond.

When Signposts are written from the app Whither, probably via a dylib, the interval between the first and second is only 4 microseconds, regardless of whether the call is made from a background or the main thread. In either case, they rapidly settle to 1-2 microseconds.

If you’re interested in measuring the performance of tasks which take hundreds of microseconds, or even milliseconds, Signposts and regular log entries have such small overhead or latency that they should be considered to be almost instantaneous, and writing either will have no effect on the performance of the code which you are trying to measure. Quantum mechanics isn’t beaten, quite, but can be safely ignored.

It’s rather harder to assess the maximum bandwidth of the log before log activity starts to reduce overall performance of your Mac. However, if each log or Signpost entry takes 2 microseconds, the absolute maximum activity would be 500,000 messages per second. Observed peaks of around 10,000 messages per minute are little more than 0.03% of that; although they may impose a small performance penalty, that is neither significant nor likely to be noticed.

From the numbers that I am seeing, the unified log and Signposts have no perceptible impact on performance, and can be used freely when desired. The problem in their use is harvesting their data and analysing it.