Getting started with signposts

One big focus of this year's WWDC is performance - both in terms of how Apple seems to have made a big effort in improving the overall performance of their operating systems and frameworks, but also in the messaging to us third party developers.

Like mentioned in several sessions during the conference, maintaining a solid level of performance is in many situations essential to providing a good user experience. As the refresh rate of the screens we render on increases (up to 120 Hz on the iPad Pro), the amount of time we (and the system) has available to render each frame shrinks, and maintaining smooth scrolling and other per-frame rendering tasks becomes increasingly challenging.

Something that can be even more challenging is debugging and identifying bottlenecks when it comes to performance. Many times performance drops are hard to reproduce and really require good information in order to be fixable.

To address this problem, Apple is introducing a new developer tool this year called os_signpost. Using this new tool, we can easily place markers - signposts - in our code that can make profiling and debugging performance issues a lot simpler. In today's WWDC update, let's take a look at how to get started with this new tool!

Bottlenecks

When we discover a performance problem in an app that we're working on, the first thing we want to do is identify where the bottleneck that's causing the problem might be. Let's say our app at some point needs to load a set of records, and by spending some time with the Time Profiler in Instruments we suspect that the problem lies within our function that loads records, that looks like this:

func loadRecords() throws -> [Record] {
    let decoder = JSONDecoder()

    return try files.map { file in
        let data = try file.read()
        let record = try decoder.decode(Record.self, from: data)
        return record
    }
}

The question now becomes, what exactly is causing our performance problems? Is it reading our files' data, or decoding their contents? Does this only happen for a certain set of files or all of them? These are questions that os_signpost can help us answer in a nice way.

Setting things up

Signposts are placed in pairs, using balanced calls to os_signpost with the begin and end types. But before we can start placing signposts, we need to create a log handle and signpost IDs. Let's first create our log handle, which Instruments uses to group signposts based on their subsystem (which in our case is the bundle identifier of our app) and category (what kind of task we're performing, in this case RecordLoading):

import os.signpost

let log = OSLog(
    subsystem: "com.johnsundell.app",
    category: "RecordLoading"
)

Next, for each file we'll create a signpost ID, that Instruments will use to match each begin and end signpost pair:

let signpostID = OSSignpostID(log: log)

Now, with the setup done, we can start placing some signposts!

Placing signposts

We'll place one signpost with the begin type before each operation and one with the type end after the operation has finished. For each signpost, we'll pass in our log as well as our signpostID. We'll also add a description containing each file's path, so that we'll be able to identify any files that are especially problematic. Here's what that looks like for reading a file:

os_signpost(
    type: .begin,
    log: log,
    name: "Read File",
    signpostID: signpostID,
    "%{public}s",
    file.path
)

let data = try file.read()

os_signpost(
    type: .end,
    log: log,
    name: "Read File",
    signpostID: signpostID,
    "%{public}s",
    file.path
)

As you can see above, we can't use Swift's normal string interpolation here. That's because we're dealing with strings of the StaticString type, that need to be fully defined at compile time. Instead, we'll use a special %{public}s format to be able to pass in our file's path as an argument.

Wrapping things up

Finally, let's add the same signposts around our call to decode each file's data as well, giving us the following end result:

import os.signpost

func loadRecords() throws -> [Record] {
    let decoder = JSONDecoder()

    let log = OSLog(
        subsystem: "com.johnsundell.app",
        category: "RecordLoading"
    )

    return try files.map { file in
        let signpostID = OSSignpostID(log: log)

        os_signpost(
            type: .begin,
            log: log,
            name: "Read File",
            signpostID: signpostID,
            "%{public}s",
            file.path
        )

        let data = try file.read()

        os_signpost(
            type: .end,
            log: log,
            name: "Read File",
            signpostID: signpostID,
            "%{public}s",
            file.path
        )

        os_signpost(
            type: .begin,
            log: log,
            name: "Decode Record",
            signpostID: signpostID,
            "%{public}@",
            file.path
        )

        let record = try decoder.decode(Record.self, from: data)

        os_signpost(
            type: .end,
            log: log,
            name: "Decode Record",
            signpostID: signpostID,
            "%{public}s",
            file.path
        )

        return record
    }
}

With the above in place, we can now select Product > Profile in Xcode to launch Instruments and start profiling. By selecting the Blank template and then adding the os_signpost instrument using the + button in the top right corner, we can now see our signposts being visualized for each file πŸŽ‰.

All that remains now is to dig into the data that Instruments is showing us, to identify what kinds of files that are problematic and what we'll need to change in our code to deal with those cases. With this new, more granular information, this process should now be much easier than before.

Conclusion

Signposts seems like a really promising new tool, especially when it comes to quickly getting more thorough information when debugging tricky performance problems and asynchronous operations. However, we've only scratched the surface of what signposts can do in this post, so I'm sure this is a topic that we'll revisit in a future weekly article on the main blog.

One question is whether we should keep the calls to os_signpost in our code base even after we're done profiling and fixing the problem. On one hand, having that information always accessible is nice - but on the other hand all those extra calls really clutter up our code and can make it much harder to read. For some use cases it might be worth keeping them around, while for others we might want to treat them more like a temporary debugging tool.

For more information about signposts and their more powerful use cases, make sure to check out the "Measuring Performance Using Logging" WWDC session.

What do you think? Will use use os_signpost the next time you need to debug a performance problem in your app? Let me know - along with your questions, comments and feedback - on Twitter @johnsundell.

Also make sure to check out the latest episode of the Swift by Sundell podcast - which is a WWDC special featuring Ben Scheirman!

Thanks for reading! πŸš€

Faster and more robust tests with Xcode 10

Synthesized conditional conformances in Swift 4.2