Yesterday, I released new versions of my RouteMap app and Signpost Kit, which enable you to measure performance in almost any app or script, by writing Signposts to the unified log. Key to the success of any method of measuring performance is the time taken to record Signposts. If that’s too long, the method is only useful when timing procedures taking seconds. To be generally useful, we need to know the latency of writing Signposts to the unified log, which is the concern of this article.

In the apps provided in the Signpost Kit, there are two simple ways to look at Signpost latency without writing any code: blowhole‘s -M option, and the multiples option in Whither.

blowhole

When you call blowhole with the -M option, in a command like
blowhole -M [N]
it executes a loop N times, writing a Signpost each time. The Swift code it uses is:
for i in 0..<count {
os_signpost(type, log: myLog, name: "blowhole", signpostID: mySpid, "blowhole %{public}@", "\(i)")
}
making it as tight a loop as possible.

Running that on an iMac Pro (3.2 GHz 8-Core Intel Xeon W), the time difference between the first and second Signpost is around 3200 ns, but then settles to around 1400 ns per loop. That’s pretty quick, at 1.4 µs per Signpost.

Whither

If you look at the source code provided, you’ll see that, with the multiples checkbox ticked, Whither executes a series of Signpost calls.

The first is identical to that in blowhole, but run from a concurrent (background) process:
for i in 0..<10 {
os_signpost(.event, log: self.myLog!, name: "timingCheckBack", signpostID: mySpid, "%{public}@", "\(i)")
}

This is repeated, but this time in the app’s main process, followed by an unrolled loop which writes a sequence of begin-end pairs starting with
os_signpost(.begin, log: self.myLog!, name: "begin1", signpostID: mySpid, "1")
os_signpost(.end, log: self.myLog!, name: "begin1", signpostID: mySpid, "2")
again in the main process.

The two for loops typically write Signposts every 1270 ns from the background, and 1350 ns in the main process, which is slightly faster than blowhole. The unrolled loop of begin-end pairs is significantly quicker, though: the first normally takes around 520 ns, following which they take about 385 ns. On one occasion, a pair was delayed and took 10500 ns. When I looked at a similar sequence on a slower MacBook Pro (2.5 GHz i7) two years ago, the begin-end time was around 500 ns.

Signpost latency

In these examples of compiled Swift code, the time overhead involved in writing Signposts was generally below 1.5 µs, and in the best case of writing unrolled begin-end pairs fell below 0.4 µs. These latencies are ideal for precision timing of events taking longer than 0.1 millisecond, and used with care they could give useful results for much briefer events, of less than 50 µs.

Is there anyone who thinks those are inadequate?

RouteMap and the Signpost Kit (including Whither, its source code, and blowhole) are available from their Product Page.