At AppSpector we often deal with debugging client applications with our tools integrated and, naturally, our own code, including the core part — mobile SDKs. We have always embraced all variety of tools available for the particular platform to speed up debugging and make the development process easier and error-prone. Thus, when we spotted WWDC 2018 session 410 “Creating custom instruments”, we couldn’t wait to build something with the new APIs.
If all you have is a hammer, everything looks like a nail. A problem worth building a custom Instruments package was not long in coming. The core part of AppSpector iOS SDK is a messaging module which, in a few words, is responsible for two-way traffic exchange between iOS and our backend. SDK sends a huge amount of events describing host app behavior and various actions, and also receives requests from the backend. The amount of traffic is big enough to require compression, so we implemented it from the very beginning, and now all messages are being compressed/decompressed at both SDK and backend sides.
At some point we decided to change the compression algorithm from LZ4 to zstd which is dictionary based and could potentially provide better compression on our type of data. As we all know, the ability to measure any changes is crucial to bring them in safely and effectively, so we decided to create a built-in mechanism to track compression rate and performance. Of course, custom instrument was the best candidate.
How potential instrument could help
Actually, almost the same could easily be achieved with simple logging, but what we wanted and what Instruments are suited for was data sampling and visualization. Imagine that a single message in a hundred experiences compression problems, its compression rate is disturbingly low, and you need to perform certain actions, e.g. establish a Bluetooth connection, to trigger it on a real device. Searching the logs for this message can be a real pain. Even if you use a service of some kind to collect and save log messages from a device, and your message has a precalculated compression rate, it’s not quite the thing. But looking at the interactive graph just like that guy at the WWDC session, being able to save collected data and compare two runs later, building custom selection rules to identify and aggregate messages with certain properties — that looked awesome.
Building an instrument
Technically Instruments is a frontend for one of the most powerful debugging platforms out there called DTrace. It came to OSX from Sun Solaris and describing it in details could take the whole book (and actually it does: https://www.amazon.com/DTrace-Dynamic-Tracing-Solaris-FreeBSD/dp/0132091518). DTrace operates with special tracers written in D language and called probes.
Before Apple introduced Instruments packages, you could have built a custom instrument by writing your own D script as a data provider and wrapping it in an instrument template. What we’ll take a look at is using os_signpost API to provide data to our instrument.
For convenience, we will build a sample project to illustrate a simple Instruments package. Our instrument for compression profiling works the same way except for the randomly generated event values we used in sample project to simulate compressed and decompressed message size. We recommend to clone the sample project and refer to it while reading.
Xcode provides a new target type called ‘Instruments Package’ available under ‘MacOS’ -> ‘Other’ section. Target template doesn’t do any magic , it just adds one file with the .instrpkg extension, which is actually an XML file describing our instrument layout and functionality. Most part of the work on building package is just writing in raw XML. Let us hope that we’ll get some task-specific editor like InterfaceBuilder or CoreData model editor soon enough.
The instrument we’ll build will use os_signpost calls as data providers. This API allows to define start and end of the event, and also pass some formatted string along with start and end calls. Getting data for the event on the Instruments side is performed by parsing this string according to its format, just as you do with ‘scanf()’.
We will be using os_signpost() for Swift and if you are writing in Objective-C , you should use os_signpost_interval_begin / os_signpost_interval_end calls. To start using these APIs we need to instantiate ‘log’ instance, because os_signpost uses os_logging subsystem for sending messages and a unique signpost identifier:
static let log = OSLog(subsystem: "com.package", category: "Behavior") static let signpostID = OSSignpostID(log: AppDelegate.log, object: self as AnyObject)
Note that subsystem and category arguments are passed to the os_log initializer. These values will be used in a package description later to match our signpost calls. We have to call ‘begin’ before our event of interest starts, and ‘end’ after it ends passing previously created log and signpost_id instances as parameters:
os_signpost(.begin, log: AppDelegate.log, name: "event-tracking", signpostID: AppDelegate.signpostID, "size: %llu", before) // your action here... os_signpost(.end, log: AppDelegate.log, name: "event-tracking", signpostID: AppDelegate.signpostID, "size: %llu", after)
Actually, that’s all we need in our app code, and we can proceed to the Instruments part.
Instrument package file is a long XML file we divided into three parts: package metadata, schema, and implementation. Let’s go from top to bottom looking through the instrpkg file of our sample project. Writing a huge amount of XML is difficult, but Xcode team added a bunch of templates for main sections of the package structure, so when you start typing some tag, you will almost always receive the suggestion for the template with basic subtags. Right after the ‘package’ tag you can see the metadata section with ‘id’, ‘title’ and ‘owner’ info. This info will be used by Instruments app to identify and install your package. ‘owner’ value will be displayed in package info when you select it for usage. You can also provide ‘version’ and ‘note’ tags here.
The next section is our schema description. This section describes the data our instrument will be operating and starts with ‘id’ and ‘title’ tags. ‘id’ is a unique value we’ll use later to reference our schema from the Instrument UI description, and ‘title’ is a value presented near the graph view in Instruments UI. Next, we have ‘subsystem’, ‘category’ and ‘name’ tags used for identifying our signpost calls, they have to match the ones we used for creating os_log subsystem handle in our app’s code. Next tags, ‘start-pattern’ and ‘end-pattern’ , define the format for parsing our messages. This format will be applied to string parameter we passed to begin/end calls. Strings starting with the question mark, ‘size-before’ and ‘size-after’, are names of the variables holding the data we pass from the app side. This is the first place we meet CLIPS expression. CLIPS is a language Apple used for data processing in Instruments, and even its brief overview deserves a separate article. If you are interested, you can navigate to CLIPS reference for more information on the language itself. At the end of the schema we have a bunch of ‘column’ tags describing data columns available for our package. We use 4 fields for each: ‘mnemonic’ is a unique column reference, ‘title’ and ‘type’ are pretty self-explanatory (full list of types can be found in Instruments documentation), and ‘expression’ tag contains CLIPS expression which result will be used as a column value. We use the input data we received in start-pattern / end-pattern section for the first two columns and simple rate calculation for the third one. The last two columns will contain string values, high / low value in a first one, and color name in a second one. These values will be calculated depending on rate value, and we’ll use them later while building Instrument UI.
This part describes UI components of our instrument and how they will be populated with data. We have some metadata here at the beginning followed by the graph, table and aggregation sections. Metadata includes package id which should match the one we used as a subsystem value for creating the os_log instance, ‘title’, ‘category’ and ‘purpose’ fields used for reference in Instruments UI, and ‘icon’ to choose an icon for your instrument.
If you have used Instruments before, you probably remember that almost any Instrument UI is divided into two main parts: graph at the top and table with data at the bottom. Tags ‘graph’ and ‘list’ are used to describe this two parts. First, to define a table we need to create it with ‘create-table’ tag referencing our schema ID. It will allow us to use data from columns we described above. After that we describe a graph part of the UI which consists of one lane. At this point we refer to our table and state which columns should be used for plotting. List tag describes the bottom part of the UI referencing the table ID just like the previous graph element and listing columns to display. Not that we skipped ‘rate-color’ column here because we use it only for coloring a graph and it doesn’t make sense to include it in our table.
Actually, this package is already almost complete, but for our task with compression profiling we wanted to have a separate data view displaying messages with compression rate below 0.15%. As finding them among all of the messages would be hard, we decided to use an aggregation tag to describe a separate view available at the table part of the Instrument UI. Aggregation section includes ‘slice’ tag which tells Instruments to display only data with ‘High’ value in the ‘rate-status’ column, and list of columns to display for each entry. We decided to display the size before and after the compression only.
To run a package and test it with an app producing signpost events, you need to build the app itself, then build the package scheme with ‘My Mac’ target. After building is done, Xcode will run a special instance of Instruments for you. This Instance contains your package embedded. Its icon is grey-scaled to distinguish it from ordinary running Instruments. After starting instruments you’ll be presented with a template selection window. Select ‘Blank’, and then press ‘plus’ icon at the top right corner of the new window. You’ll see the list of packages available and your package among them. It will be marked with ‘debug’ badge indicating that it was run from the Xcode. Drag it to Instruments window or just double-click to add, select device and app in upper left corner and press ‘record’ button.
If you want to share your newly built package with your colleagues, all you need is .instrdst file under ‘Products’ folder in Xcode. Running it will show you a small window with package info and ‘install’ button. Install it, and you’ll have it in your Instruments packages list.
Most of the time debugging is about searching for the root of the problem, not fixing it, as fix often takes significantly less time than looking through the logs, attempts to reproduce the issue, and all the other activities of exploratory kind. Choosing the proper tool is the most important part. Sure, you can do it the old way, say detect leaks just by looking at the memory dump or logging objects lifetime, but with a leaks instrument this will be much faster and easier. Instruments provide you with ability to choose specific point of view to observe your app or its part, sometimes it’s all you need to identify the problem. This tool was already awesome, but Xcode team managed to make it even more powerful by allowing developers to build a custom instrument.
Building a custom Instrument is easy and fun, and you will only need to spend an hour or so to save much more time later. Of course, it would be great to have more docs and some editor for package files, but even in the current state it could be extremely useful, especially for medium-sized and big projects.
- WWDC 2018, session 410 “Creating Custom Instruments”, the main resource available on this topic
- John Sundell article about os_signpost API, a brief introduction to signpost API and it’s integration in Instruments
to Kacper Harasim who was extremely kind answering questions and helped a lot in understanding how everything works.