Using Signposts to Diagnose Performance Issues

Episode #348 | 26 minutes | published on August 8, 2018 | Uses Xcode-10.0-beta2

Subscribers Only

Signposts are a special part of the Unified Logging and Activity Tracing system. They allow you to mark point-in-time events that occur in your code, or track the duration of operations by specifying the begin and end for an activity. These can be visualized in Instruments to get a rich, high level view of how these operations are performing, how often they are occurring, and how long they are taking. In this episode we will see how to add signposts to an app and how to view these signposts in Instruments.

This episode is part of a series: Unified Logging and Activity Tracing.

1. Introduction to the Unified Logging Framework 10 min

2. Using os_log to Log Messages 12 min

3. Private Data and the log Utility 6 min

4. Streaming Logs with the log Tool 5 min

5. Activity Tracing in Swift 20 min

6. Using Signposts to Diagnose Performance Issues 26 min

Episode Links

3 Key Performance Techniques for iOS 12 Developers - a great blog post covering signposts and more. Lots of great stuff to learn here.
Measuring Performance using Logging - WWDC 2018 Session 405. This session talks about using signposts and building custom signpost instruments.

Getting Started

First, import the modules we'll be using at the top of the file:

import os.log
import os.signpost

The signposts will be added to an OSLog, so we'll need to add one of those. I chose to put this in a separate file so I could use it from anywhere in my app:

import os.log

struct SignpostLog {
    static var pointsOfInterest = OSLog(subsystem: "com.ficklebits.SignpostDemo", category: .pointsOfInterest)
    static var general = OSLog(subsystem: "com.ficklebits.SignpostDemo", category: "general")
    static var json = OSLog(subsystem: "com.ficklebits.SignpostDemo", category: "json")
}

The signposts in Instruments are grouped by the log we choose. Additionally, if we want to use point-in-time signposts, we have to use a special .pointsOfInterest category.

Measuring Performance of Cell Configuration

In our view controller we can add begin/end signposts where we configure our cells, to measure the time this takes for each. If we are doing anything slow within these methods it will be clear to see with these signposts.

os_signpost(.begin, log: SignpostLog.general, name: "Configure Cell", "Story %d - %s", story.id, story.title)
configure(cell: cell, with: story)
os_signpost(.end, log: SignpostLog.general, name: "Configure Cell")

Note here that we use the same name, so these calls can get correlated together. The begin signpost has metadata attached to it that we'll be able to see within instruments.

Measuring Asynchronous Operations

The begin/end calls are not always inline like that, and often we'll have to associate begin and end signposts using something other than the name. For this we can use signpost ids.

private func loadStory(with id: Int, indexPath: IndexPath) {
        let spidForStory = OSSignpostID(log: SignpostLog.general, object: id as AnyObject)
        os_signpost(.begin, log: SignpostLog.general, name: "loadStory", signpostID: spidForStory, "Load Story %d", id)
        let task = newsAPI.loadStory(id: id) { result in

            switch result {
            case .success(let story):
                os_signpost(.end, log: SignpostLog.general, name: "loadStory", signpostID: spidForStory, "%s", story.title)

                // ....                
            case .failed(let error):
                if self.isCancellationError(error) {
                    os_signpost(.end, log: SignpostLog.general, name: "loadStory", signpostID: spidForStory, "Cancellation")

                } else {
                    os_signpost(.end, log: SignpostLog.general, name: "loadStory", signpostID: spidForStory, "Error: %@", error as NSError)                    
                }
            }
        }

        // ....        
    }

For each of these calls we add metadata to the end call to add more information when viewing this in Instruments.

Points of Interest

Another useful application of signposts is marking events that occur in the app. We can use this to visualize how long the app takes to start up and display the first cell, for instance.

We'll add signpost events to app launch, view controller lifecycle events, and the display of the first cell, like this:

// AppDelegate.swift
func application(_ application: UIApplication, willFinishLaunchingWithOptions launchOptions: [UIApplication.LaunchOptionsKey : Any]? = nil) -> Bool {
        os_signpost(.event, log: SignpostLog.pointsOfInterest, name: "willFinishLaunching")
        return true
    }

    func application(_ application: UIApplication, didFinishLaunchingWithOptions launchOptions: [UIApplication.LaunchOptionsKey: Any]?) -> Bool {

        os_signpost(.event, log: SignpostLog.pointsOfInterest, name: "didFinishLaunching")

        return true
    }

// ViewController.swift

    override func viewDidLoad() {
        super.viewDidLoad()
        os_signpost(.event, log: SignpostLog.pointsOfInterest, name: "ViewController-viewDidLoad")

        // ....
    }

    override func viewWillAppear(_ animated: Bool) {
        super.viewWillAppear(animated)
        os_signpost(.event, log: SignpostLog.pointsOfInterest, name: "ViewController-viewWillAppear")
    }

    override func viewDidAppear(_ animated: Bool) {
        super.viewDidAppear(animated)
        os_signpost(.event, log: SignpostLog.pointsOfInterest, name: "ViewController-viewDidAppear")
    }

And then finally when the first cell is displayed:

    override func tableView(_ tableView: UITableView, willDisplay cell: UITableViewCell, forRowAt indexPath: IndexPath) {
        if indexPath.row == 0 {
            os_signpost(.event, log: SignpostLog.pointsOfInterest, name: "Will Display First Cell")
        }
    }

View on Github

Download