os_signpost and XCTestObservation -- detecting performance issues with your test suite

The new os_signpost API allows easy instrumentation of critical areas of your code, and makes it easier to dig in to interface builder and sort out what's happening when -- even for notoriously hard-to-pin-down areas like concurrency.

No doubt, many people are already adding these calls to their libraries, apps and tools wherever it makes sense in order to be able to better debug issues as they arise in development -- but what if you could leverage your test suite to help you find issues before a developer or customer runs in to it?

Enter the XCTestObservation protocol

In Xcode 7.2, Apple introduced the XCTestObservation protocol, and XCTestObservationCenter to enable developers to get delegate callbacks during test runs and do whatever work they may need to do outside of the normal setup and teardown of a single test.

Any number of classes can be registered to observe test runs, and an observer can choose to detach at any point as well, however in general it seems likely that you'll only have a single observer in most cases. We'll cover an example of how to have multiple at the end of this article, if you're so inclined.

Using XCTestObservation

It's not immediately obvious exactly what one needs to do to set up and register a test observer, so in brief:

1. In your test target, find the Info.plist and add a key: Principal class (or NSPrincipalClass) with the class name of your test observer as follows: $(PRODUCT_NAME).TestObserver --Note the ${PRODUCT_NAME} simply provides the name of the test bundle, which is part of the full class name for a Swift class.
2. Create a class as follows:

class TestObserver: NSObject, XCTestObservation {
	  // This init is called first thing as the test bundle starts up and before any test 
	  // initialization happens	
    override init() {
        super.init()
		  // We don't need to do any real work, other than register for callbacks
        // when the test suite progresses.
        // XCTestObservation keeps a strong reference to observers
        XCTestObservationCenter.shared.addTestObserver(self)
    }
}

3. Add the relevant delegate methods for your implementation (see our example here for what's available).

Instrumenting our tests with Signposts

Once the test observer is set up, we'll add in calls to os_signpost with relevant metadata for each level of the test suite, that is: The test bundle starting, each test suite, and teach test case - start and finish.

Here's a snippet of just the test bundle delegate methods:

class TestObserver: NSObject, XCTestObservation {

	  // Create a custom log subsystem and relevant category
    let log = OSLog(subsystem: "net.davelyon.os-log-test", category: "signposts")

    override init() {
        super.init()

        // XCTestObservation keeps a strong reference to observers
        XCTestObservationCenter.shared.addTestObserver(self)
    }

    // MARK: - Test Bundle

    func testBundleWillStart(_ testBundle: Bundle) {
        let id = OSSignpostID(log: log, object: testBundle)
        os_signpost(.begin, log: log, name: "test bundle", signpostID: id, "%@", testBundle.description)
    }

   func testBundleDidFinish(_ testBundle: Bundle) {
        let id = OSSignpostID(log: log, object: testBundle)
        os_signpost(.end, log: log, name: "test bundle", signpostID: id, "%@", testBundle.description)
    }
}

Let's break this down a bit more and look at what each step is doing:

func testBundleWillStart(_ testBundle: Bundle) {

is called when the test bundle starts (the whole test target, typically).

    let id = OSSignpostID(log: log, object: testBundle)

Signposts require unique identifiers to match the start and end of full event, and by providing an instance of an object we can ensure that we get the same unique signpost ID at the start and end of the event.

    os_signpost(.begin, log: log, name: "test bundle", signpostID: id, "%@", testBundle.description)
}

Call os_signpost and tell it that this is a "begin" event (which means it should expect a matching end event at some point). Call the even "test bundle" and identify this instance of the event with the signpost ID we created. Lastly, provide the additional context of the test bundle "description." The last step is most important as we look at test suites and test cases, however it's still useful to know the full context of a test bundle as well, and would even allow us to track across multiple bundles as well.

There's more events we care about, but they're largely the same, so please review them at your convenience

Running in Instruments:

First, make sure you've set the "Build Configuration" option for Analyze to "Debug" (or instruments won't be able to run your tests and attach to them).

"Analyze" your tests by navigating to the "Test navigator" panel on the right-hand side of Xcode and right-click on your test bundle, then choose "Profile (Test Suite Name)"

When instruments opens, choose a "Blank" instrument, and then from the dropdown, choose "OS Signpost" and drag it on to the window.

Hit the "Record" button to run your tests.

That's all there is to it

Once you've got these in place, you can select a time interval and look at what's going on both in your test suite, and in your app code.

Other os_signpost options:

Allow signposts to be toggled on/off, if needed:

lazy var log: OSLog = {
    if ProcessInfo.processInfo.environment.keys.contains("TEST_SIGNPOSTS_ENABLED") {
        return OSLog(subsystem: "net.davelyon.os-log-test", category: "example")
    }
    return OSLog.disabled
}()

Other XCTestObservation options:

Add multiple Observers:

// Add to your test suite "Info.plist": "Principal class" => "$(PRODUCT_NAME).TestObservationConfiguration"
class TestObservationConfiguration: NSObject {

    override init() {
        XCTestObservationCenter.shared.addTestObserver(TestObserver())
        XCTestObservationCenter.shared.addTestObserver(OtherTestObserver())
    }

}

Remove an Observer:

XCTestObservationCenter.shared.removeTestObserver(someInstance)

Documentation:

XCTestObservationCenter

XCTestObservation