You Should All Build This Custom Instrument for Your App

Note: This was written shortly before WWDC 2020, but you might only read it afterwards. So anything in here is already available, you don’t need to download the beta for it or wait until autumn to use it. I’ll update this if anything relevant to this article comes out from WWDC.

Most of you have probably worked with an app or are currently working with an app for which a significant part of the functionality relies on talking to a server via HTTP. When something doesn’t work as expected or you simply want to understand an area of the code you are unfamiliar with, it’s often useful to look at the HTTP calls going back and forth between the server. What kind of calls are made? What exactly is the server sending? To do so, you are likely use a tool like Charles Proxy or Wireshark.

However, these tools are often rather complex to use and especially to set up. They may require you to set up a custom SSL certificate and jump through multiple hoops to make the device trust it. They also show a lot of information you might not actually need to understand your application. At the same time, it’s hard to cross-reference them with whatever else is going on in your application. So what if I told you that instruments could actually do a lot of that work as well, with a little help from you and could display it in a manner that’s much better suited to what your application is actually doing?

As preparation for WWDC next week¹, I’ve been (re)watching a couple of talks from previous WWDCs. Somehow, I had completely missed that the core of Instruments had been rewritten to unify the instruments and make it much easier to build custom instruments for Xcode 10. Also, WWDC 2019 had a great introduction to instruments, something I’ve been missing for years.

Ok, cool, so you can now write custom instruments to measure things Instruments might not ordinarily measure. But what can you measure and how easy is it? “Pretty much anything” and “medium difficulty, little time effort”, I’d say. Generally, you can do most things you need by writing an XML file that specifies how to translate signposts from your code into data to display in instruments and the XML you write is not particularly complex. The main hurdle is that the “code” you write will likely be quite different from what you are used to, there are only very few examples to follow, the documentation only gives a high-level overview of how to do it and while Xcode actually validates the XML file pretty strictly there is little help of how to fix an issue and no autocompletion. But with a bit of time you can find the pieces you need, and if you have an example to adapt you can actually make progress rather quickly. So I’m going to give you such an example and try to list all the useful links as well.

But let’s start at the beginning: I want anyone of you who has used Charles or Wireshark before to debug your app, or who has an app that makes a lot of HTTP requests, to build an HTTP tracing instrument custom for your app or at least framework. It will look like this:

It took me about a day to get this prototype up and running (after watching the relevant WWDC videos). If you don’t care about the rest and just want to see the code, it’s here.

Overview

What we are doing here, and what’s the easiest way to get a custom instrument, is to use os_signpost. You use it to log .events or .begin and .end signposts. You then configure a custom instrument to parse these os_signpost intervalls and extract the extra values you logged to it to configure how to display them in a graph, how to group them, which ones to filter out and how to configure lists and tree/outline views in the detailed pane of Instruments.

We want to build an instrument that displays all HTTP requests that go through our networking library as intervalls (start + end), so we can see how long they take and cross-reference them with other things going on in our app. In this blog post, I’m using Alamofire as the Networking library to instrument and Wordpress as the app to profile, simply because both are open source. But you should be easily able to adapt all the code to your networking library.

Step 0: Familiarize Yourself With the Instruments App

Getting Started with Instruments (Session 411 from WWDC 2019) is a really good overview of instruments, at least watch the “Orientation” part to get familiar with the terminology, like instruments, tracks, lanes, traces, templates, detail view, etc.
Watch Creating Custom Instruments (Session 410 from WWDC 2018) to get an idea of what we are doing. If you are impatient, it’s enough to watch the “Architecture” (for additional details how Instruments works and what you are actually configuring) and the “Intermediate” part. Don’t expect to understand every detail while watching it, it’s a lot of stuff in one session and they don’t explain every detail due to time limitations. I had to watch it multiple times and find additional documentation before I actually managed to get my instrument working in the way I wanted. However, I’m trying to fill in the gaps below.

Step 1: Log the Data You Need to Signposts

We want to build a signposts-based instrument, so we need to log our data via signposts. Alamofire sends Notifications whenever a request starts or completes, so all we need is something like this²:

NotificationCenter.default.addObserver(forName: Notification.Name.Task.DidResume, object: nil, queue: nil) { (notification) in
    guard let task = notification.userInfo?[Notification.Key.Task] as? URLSessionTask,
        let request = task.originalRequest,
        let url = request.url else {
            return
    }
    let signpostId = OSSignpostID(log: networking, object: task)
    os_signpost(.begin, log: SignpostLog.networking, name: "Request", signpostID: signpostId, "Request Method %{public}@ to host: %{public}@, path: %@, parameters: %@", request.httpMethod ?? "", url.host ?? "Unknown", url.path, url.query ?? "")
}

NotificationCenter.default.addObserver(forName: Notification.Name.Task.DidComplete, object: nil, queue: nil) { (notification) in
    guard let task = notification.userInfo?[Notification.Key.Task] as? URLSessionTask else { return }
    let signpostId = OSSignpostID(log: networking, object: task)
    let statusCode = (task.response as? HTTPURLResponse)?.statusCode ?? 0
    os_signpost(.end, log: SignpostLog.networking, name: "Request", signpostID: signpostId, "Status: %@, Bytes Received: %llu, error: %d, statusCode: %d", "Completed", task.countOfBytesReceived, task.error == nil ? 0 : 1, statusCode)
}

When the requests starts, we log a .begin signpost, when it completes, we add an .end signpost. The signpostId is used to match an end call with a corresponding begin call, to make sure we close the correct interval, if multiple requests are happening in parallel. Ideally, we would store the signpostId on the request object, to make sure we use the same one for .begin and .end. However, I didn’t want to modify the Request type in Alamofire, so a workaround is to use OSSignpostID(log:, object:) and pass an identifier object to it. We use the underlying URLSessionTask object here as this will hopefully be the same in both cases. And with the object being the same, OSSignpostID(log:, object:) will return us the same id when calling it multiple times.

We log data via a format string. You probably want to make sure, to always separate two arguments with some fixed string in-between to make it easier to parse on the instrument-side and also make the parsing easier to understand. Note that you don’t need to log data in the .end call if you’ve already logged it in the .begin call. Both will be combined to one interval and you’ll have acces to all of them.

Step 2: Create a new custom instruments Xcode project.

Follow the steps in Creating Custom Instruments (Session 410 from WWDC 2018) or in the Instruments app help - Create an Instruments Package project to create a new Instruments Package project in Xcode. This will give you a basic Xcode project with a .instrpkg file. You’ll specify all the details there.

Step 3. Do all the rest 😆

Basically, you’ll follow the steps outlined in the Instruments app help - Create an instrument based on signpost data. While all the steps in there are correct, they are lacking a lot of detail, so it’s good to have an example of an actual custom instrument. Take a look at mine here. You’ll basically need these parts:

A Schema

This tells instruments how to parse the data from your signposts into variables you can use. You define a pattern that extracts variables from your logged messages and assign those to columns.

<os-signpost-interval-schema>
	<id>org-alamofire-networking-schema</id>
	<title>Alamofire Networking Schema</title>

	<subsystem>"org.alamofire"</subsystem>
	<category>"networking"</category>
	<name>"Request"</name>

	<start-pattern>
	    <message>"Request Method " ?http-method " to host: " ?host ", path: " ?url-path ", parameters: " ?query-parameters</message>
	</start-pattern>
	<end-pattern>
	    <message>"Status: " ?completion-status ", Bytes Received: " ?bytes-received ", error: " ?errored ", statusCode: " ?http-status-code</message>
	</end-pattern>

	<column>
	    <mnemonic>column-http-method</mnemonic>
	    <title>HTTP Method</title>
	    <type>string</type>
	    <expression>?http-method</expression>
	</column>
	<!-- and lots more columns like that -->
</os-signpost-interval-schema>

The mnemonic is the identifier of the column that you use to refer to it later on. I somehow felt weird naming the columns the same as the variables, so I prefixed them with column. But from what I can tell there is no need to do that.

An Instrument

An Instrument consists of the basic definition:

<instrument>
    <id>org.alamofire.networking.instrument</id>
    <title>Alamofire</title>
    <category>Behavior</category>
    <purpose>Trace HTTP calls made via Alamofire, grouped by method, host, path, etc.</purpose>
    <icon>Network</icon>
    
    <create-table>
        <id>alamofire-requests</id>
        <schema-ref>org-alamofire-networking-schema</schema-ref>
    </create-table>

    <!-- rest of the instrument definition -->
</instrument>

This is fairly basic stuff. Most of these fields are free-form text or refer to stuff you defined previously (schema-ref). But category and icon can only have a small set of values defined here and here.

A Graph Inside an Instrument

A graph defines the, well, graphing part of the instruments UI, the visual representation you see in the track area. It looks roughly like this:

<instrument>
    <!-- Basic instrument definition -->
    <graph>
        <title>HTTP Requests</title>
        <lane>
            <title>the Requests</title>
            <table-ref>alamofire-requests</table-ref>
            
            <plot-template>
                <instance-by>column-host</instance-by>
                <label-format>%s</label-format>
                <value-from>column-url-path</value-from>
                <color-from>column-response</color-from>
                <label-from>column-url-path</label-from>
            </plot-template>
        </lane>
    </graph>
    <!-- other parts of the instrument --> 
</instrument>

You can have different lanes and you can use a plot-template to have a dynamic number of plots in a lane. My example also contains an example for a simple plot. I’m not really sure why both graph and lane have a title. In addition to that, each plot in a plot-template also gets a label from label-format 🤷.

A List, Aggregation, Or Something Else for the Detail View

With just a graph, Instruments would look somewhat empty. You want to display something in the detail view as well. You do so by using a list, aggregation, or narrative. Maybe more, that I haven’t figured out, yet. An aggregation looks something like this:

<instrument>
    <!-- Basic instrument definition -->
    <aggregation>
        <title>Summary: Completed Requests</title>
        <table-ref>alamofire-requests</table-ref>
        <slice>
                <column>column-completion-status</column>
                <equals><string>Completed</string></equals>
        </slice>
        <hierarchy>
            <level>
                <column>column-host</column>
            </level>
            <level>
                <column>column-url-path</column>
            </level>
        </hierarchy>
        
        <column><count/></column>
        <column><average>duration</average></column>
        <column><max>duration</max></column>
        <column><sum>column-size</sum></column>
        <column><average>column-size</average></column>
    </aggregation>
    <!-- other parts of the instrument --> 
</instrument>

a list looks like this:

<instrument>
    <!-- Basic instrument definition -->
    <list>
        <title>List: Requests</title>
        <table-ref>alamofire-requests</table-ref>
        <column>start</column>
        <column>duration</column>
        <column>column-host</column>
        <!-- Lots more columns -->
    </list>
    <!-- other parts of the instrument --> 
</instrument>

Bonus Material

With this, you are basically done 🤷. However, you also haven’t done much more than described in the WWDC video and I promised to fill in some gaps.

My example instrument constains a couple more nice things.

A small CLIPS expression so the interval is colored based on whether the request was successful or not. You can find valid color values in the Instruments Engineering Type Reference.
With the plot template, you can draw multiple plots in one lane, and e.g. have one plot per host as in my example. However, you can have more than one level of hierarchy and can allow the user to expand or collapse the details. To do so, you’ll need to use the <engineering-type-track> element to specify your hierarchy and then add augmentations for the different hierarchy levels to add graphs and detail views. Also, don’t forget to activate your augmentation inside the relevant instrument.

How to Go Further

If you haven’t seen it from the links before, there is actually a complete reference, for all the stuff you can put into the .instrpkg file. E.g., it will tell you, which elements are valid inside an <instrument>-element or from which icons you can choose for your instrument. One gotcha: Order actually matters. So, e.g. in an <instrument>, <title> must appear first, then <category>, the other way round is invalid.

Watch Creating Custom Instruments (Session 410 from WWDC 2018) again and look out for the parts that you need. There is also example code from a WWDC 2019 session, which is where I found the usage example for <engineering-type-track>.

CLIPS is the language used to write custom modelers (not covered here), but can also be used for short expressions during the column declaration. The documentation about the language has much more than you need. The main thing you probably need to know to write expressions for yourself: CLIPS uses prefix notation, so instead of ?a + ?b you’d have to write (+ ?a ?b).

Debugging

It’s a good idea to always add the os_signpost instrument to your trace document as well. This way, if something doesn’t work as expected, you can also check whether your data wasn’t logged correctly, or your instrument didn’t interpret it correctly.

What I Haven’t Figured Out Yet

How to use values that Instruments gives you out of the box and displays in the UI (e.g. the duration) in expressions for column definitions (e.g. to make a transfer rate column by dividing the bytes-received by the duration).
How to display anything in the extra detail area. It feels like it’s only for call stacks. I’d love to display e.g. a JSON body of a selected request there, but haven’t found any example that actually populates it.

What This Instrument Can Do

Work in Progress

For now, download it and just try it out.

Ok, and some other reasons. 😉 ↩
The full code for logging in my example is in the Logger.swift file. It’s targeted at Alamofire 4.8 because that’s what the current version of the Wordpress iOS app is using, even though at the time of writing, Alamofire 5 is already out. Due to the notifications, it’s easy to add this logging code without modifying Alamofire itself, however if you have a custom networking library it might be easier to add the logging to the library itself to get access to more details. ↩