Episode #348

Using Signposts to Diagnose Performance Issues

Series: Unified Logging and Activity Tracing

26 minutes
Published on August 8, 2018

This video is only available to subscribers. Get access to this video and 572 others.

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.

Episode Links

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")
        }
    }

This episode uses Xcode 10.0-beta2.