Building custom Xcode Instruments package, XML strikes back
“Write more than one” they said…
Not so long ago I started playing with custom Instruments packages. I was excited after Apple WWDC session 410 last year and thought it would be great to build something. In my previous article I described overall package architecture, some of the pitfalls in development workflow and how in AppSpector we had built custom package to track traffic compression in our SDK. During the 410 session Apple engineers said: “Build more than one instrument” on a separate slide. So I thought — why not? Custom package for Instruments is a perfect tool to implement highly specific debugging flow. Everyone knows how long one can struggle with a bug only because you have no idea what’s going on. As soon as you find “point of view” to look at the problem from — you are almost done. The fix is always something like 10% and finding that correct view angle is what takes the rest of your time. Thinking of some ideas for a package I came across a great article by CossackLabs [1] about open tracing framework and its implementations. The idea of visualizing continuous processes inside your app looked like a perfect candidate for being an instrument. Perfect examples of such processes are any actions performed in the context of different view controllers, operations stacked in queues or client — backend message exchange. If I only knew that implementation will take 32 hours ;)
Package architecture
Let’s start with a basic approach: to implement open-tracing-like graphs I decided to use graph element which looked like the best choice. Open tracing framework deals with two basic ideas of scope: a context where something is happening; and span — some activity inside a scope. Scopes within the package implementation has start and stop events, unique names and the result: success or failure. This is greatly simplified in comparison to what mature open tracing frameworks suggest but enough for experimenting with graphs in packages and for being useful. Package scheme is not very complicated. I’m not going to dive deep into elements described in the first part and I will only tell a bit about graph specific things. You can look through it here:
https://github.com/appspector/Tracer/blob/master/TracerPackage/TracerPackage.instrpkg
The first problem I faced when I build a raw implementation during a weekend was that graph lane appeared in UI only after the stop event was sent. I wanted to display it from the start event and highlight with different color those spans which are running at the moment. Thanks to Kacper, Apple engineer participating 410 session, I figured out that instruments have a special structure for this called `open-interval-template`. It’s a structure which defines fields available to the package between the start and the end events.
The graph itself is described with `graph` node, which contains fields like title and reference to the table to get data from; `plot-template` structure describes graph lanes displayed. The example below means we’ll have a separate lane for each unique scope and it will get its name from a scope-name variable. Last two tags under `plot-template` describe lines inside the lane, the color will be taken from `status-color` and label from `span-name`.
Another interesting thing is that `open-interval-template` can only operate variables which appear in the start pattern. This totally makes sense because when you display started but not finished event your code can’t use data from the end pattern. Also in the last two columns of the table we calculate the color for the line and status label, to do so we need to know the state of the event — is it running or already finished? The only way I see to resolve this is to check the variables present in the end pattern only. That’s why you see `span-name-started` and `span-name-stopped` variables in the start and the end patterns. First is used for drawing a span name on a line and second to distinguish running spans from ended. This is one of the ugly things about custom packages and it feels like it should have another, more elegant solution.
First try
I was excited to try tracer on real code so I started to look for a good example. The first try was AppSpector SDK and message processing module. Each message, incoming and outgoing, passes through a couple of steps: serializing, packaging, compression and finally sending. Sometimes messages could wait in a queue due to different reasons like network failures etc. This looked like a perfect candidate so I inserted tracer calls and started recording expecting a picture as in an open tracing manual with lots of overlapping lanes. But the actual result was a bit different:
Spans duration matters. Unfortunately, if you have milliseconds duration spans with seconds intervals between them, Instruments scales graphs and all you see are some green dots. Only zooming allows to see actual spans:
Definitely would be great to have the ability to make timeline nonlinear so seconds passed between tracked events will occupy less space than millisecond long action.
Operations
Looking for the next example I decided to try the BitBot [2], Bitrise CI client I wrote not so long ago. It has lots of NSOperations for syncing, observing, and loading files. So visualizing operations could be fun, together with queues those are perfect candidates for scopes and spans. Also, operations may finish normally or can be canceled, so span status could be useful. The problem was placing tracer calls on operations start and end, I didn’t want to do it manually and clutter code with lots of calls needed only for debug. Fortunately, objective-c is an extremely dynamic ecosystem, runtime and features like KVO is what we need here. After playing for some time with NSOperation I’ve ended up with the next approach: swizzling `addOperation` on a queue and ’start’ on NSOperation, subscribing to `isExecuting` and `isFinished` key paths and tracing operation start and stop events on appropriate KVO calls. This time result was much closer to what I expected:
This looks more useful and convenient, especially if you have lots of operations in your app. All you need is package and tracer code which is available on git repo [3] and via CocoaPods. Only one call to `startTracingOperations` and you are ready.
Conclusions
So, now I’ve built two packages, just like guys from Apple suggested. You may ask if there are any changes. Not really. I still think custom packages are awesome to build highly specialized debug tools, used only inside your project. It saves you tons of time also being almost useless for others 🙂 In case you work on the middle+ size project you might already have a set of such tools. Instruments package could perfectly fit there. On the other hand, developing instrument can still be a pain in the ass: almost no documentation, no code examples from Apple, need to write XML manually (in 2019?) and no one (except Apple guys) can help you. Go for it if this compromise works for you. I’m thinking about building something with custom data modelers or even use features not covered in session 410. But for now, this idea looks scary and almost like a reverse-engineering task.
