Getting Started with Instruments

Good morning, and welcome to Getting Started with Instruments. My name is Tibet Rooney-Rabdau and with me today are my teammates, Ben Mitchell and Anand Subramanian.

When I think about delivering a great user experience, I immediately think about performance.

Responsiveness builds trust between the user and your app. No matter how much I love the UI of an app, when I encounter a spinning gear, or a poor battery life, my overall experience with the app is diminished.

It is important to remember these areas when trying to create a great user experience in your app. In today's session, we will share with you our favorite tool to measure performance - Instruments. This is a great session for those who are new to Instruments and are looking to better integrate Instruments into their engineering workflow.

It is important to measure performance early and often, because regressions can be introduced anywhere in the development cycle and can have a compounded effect. In fact, I like to think of Xcoded Instruments as best friends, so I keep instruments in the dock beside Xcode as a reminder to proof that early and often throughout the engineering process. Today we'll start out with an orientation of Instruments, its features, and a tour of its user interface.

Then we'll show you how to profile your app to measure the time taken by various operations. We'll figure out what kind of work and how much work your app is doing by using a tool called Time Profiler. In the last section, we'll talk about adding Signposts to your application to gain insight into your app's behavior. Let's get started with a walkthrough of Instruments. Instruments is a powerful performance analysis and testing tool that's part of Xcode toolset. Instruments can help you profile your apps on all platforms - iOS, macOS, watchOS, tvOS - in order to better understand and optimize their behavior and performance.

You can use Instruments during development, testing, and debugging. Also, I have good news. If you have Xcode already, you already have Instruments. From Xcode's product menu, choose Profile. Although Instruments is embedded within and is often used with Xcode, Instruments is a separate app which may be used independently as needed. You are free to choose how you start your performance analysis quest. Now, I'll start using the word Instruments in two different ways.

We've already talked about the Instruments app. Why is it named that? Because it provides tools called Instruments that are used to profile errors in your application.

In areas where it might be hard to understand what I'm referring to, I'll refer to the application as the Instruments app.

An Instrument collects time series trace data from infrastructure that is inserted into important parts of apps, processes, and the operating system.

We sometimes refer to the data an Instrument collects as a treat.

Here we have a couple of my favorite Instruments. The Time Profiler Instrument on the left uses infrastructure provided by the operating system to collect call stacks of relevant threads at a fixed interval.

The Points of Interest instrument on the right collects data from important areas of your app that you can highlight using various APIs such as Signpost API. When you first open Instruments, you're presented with a list of templates similar to the templates in a pages or numbers document. A template provides a preconfigured collection of Instruments to help you answer a performance question, similar to how the page's birthday card template provides a document structure to help you create a birthday card. There are too many templates to cover in this short session, so we will focus on the Time Profiler template which contains the two Instruments I just mentioned - Time Profiler and Points of Interest, as well as others.

These Instruments are great tools for understanding responsiveness and your app's utilization. When you first open the Time Profiler template, you're presented with this blank document ready for Profiling. So, the top right, you can add additional Instruments to this document by clicking the Add Instruments button.

Then, the Instrument's app shows the Instrument's library palette, which contains a complete list of available Instruments.

From here, you can find new Instruments and drag them into the document to gather more data.

So, the top left, we have the Profiling Controls. This allows you to record, pause, and stop data collection. Beside the Profiling Controls is the Target Area. The Target Device List on the left allows you to select the device on which you wish to profile. This is similar to the Xcode Target Area where you choose the device and the process to Profile on the device.

Typically you will choose your app's process as your Target Process, but for instance, if you're Profiling a shared extension, you would choose your extension Process, which will be separate from your app. When I start recording in the Time Profiler template, the document will start being populated with trace data. As an aside, recording with Instruments uses System Resources, just like your app does. To minimize its impact on your app, Instruments also offers a feature called Last Few Seconds Mode, sometimes called Windowed Mode.

Windowed Mode keeps Instruments from analyzing or displaying results until recording ends and ignores events prior to the last few seconds of recording. This is helpful when you just want to start recording and select stop when you see a problem. Some templates use this mode by default because they gather a lot of data over a short period of time.

Now that I've just finished recording in the Time Profiler template, a lot of trace data has been populated into various parts of this window. This may look like a lot, so let's go on a side quest to learn what each part does.

The top portion of the window contains the Track Viewer. A Track shows time series trace data corresponding to one source of events, such as the process, thread, or CPU core. A single Instrument may contribute trace data to multiple Tracks. In this example, three Tracks are visible. The top Track is a summary of our application's CPU utilization provided by the Time Profiler Instrument.

The next Track shows data collected from the Points of Interest Instrument, which Anand will show you later. Additional Tracks follow breaking things down in finer detail. A given Instrument's trace may have dozens of Tracks.

You can use the Track Filter to just show the Instruments or break it up by thread, or by CPU core. You can also get more specific and search for Tracks by name. Lower down in the window, the detail view allows you to explore the trace data for the selected Track. In this example, with the Time Profiler Track selected, we can explore the functions called on each thread during the trace. To the right side of the Detail View, you'll find the Extended Detail View within the Inspector.

This is a view that may provide richer information from the Instruments in use, depending on current context and selection. In this example, because I'm using Time Profiler, I have a summary showing the heaviest call stack. Another way to see what is happening at a moment in time is through the Inspection Head. The Inspection Head is a selector which can be placed at a specific time in the trace in order to select all traced events or intervals occurring at that time. Additional details about the selected events are displayed in Hovering Labels. The Detail and Extended Detail views are updated to focus on information about the selected events where applicable.

We've finished our side quest and now better understand the Instruments' User Interface. Everything shown in the window is part of a trace document. The trace document contains any Instruments configured for Profiling along with collected data and views you're using to analyze the results.

The Instruments app can save and reopen these trace documents, allowing you to explore old results or share them with a teammate for investigation. With that, I would like to welcome my teammate, Ben Mitchell, to the stage, so he can show some of these things in action. Thank you! Thanks, Tibet. Hello, World. My name is Ben Mitchell and as Tibet mentioned, I'm going to show you how to Profile your application using Instruments. Let's get started.

For those of you who saw some sessions at last year's conference, WWDC2018, you might recognize the Solar System app. We shipped it about a year ago, and we've gotten some good feedback from our customers. But, also some less-than-awesome feedback; in particular, in areas of performance. Our customers have reported some responsiveness issues, particularly on older devices. I was able to reproduce one of these before the session and I'd like to demo it to you know with Instruments attached so we can see if we can fix it. Let's dive right in.

With the application already running, I'll just open Instruments.

The Instruments Template Selector already has Time Profiler chosen, because I've used it previously. Time Profiler is a great tool for looking at issues that occur over a particular window of time. I'll select Time Profiler and using the Choose button, will open a new trace document. Because I didn't launch this from Xcode, the first thing I need to do is select which process I'm going to trace.

Using the target selection area, I'll click All Processes and select the Solar System Mac application that's already running. To the right, you can see a number. That's the process identifier and it appears in Activity Monitoring. We've selected the application, and now we'll click Record in the top left of the window.

There we go. Instruments is recording.

I'll switch over to the app.

The Solar System app supports a number of gestures on the Track Pad. It supports clicks and drags, but also pans, pinch to zoom, and so on. And our customers have reported that when they're performing these operations and they press command + R to reload data, the user interface freezes and the dreaded Spinning Wait Cursor appears. You may know it by some other names. That's not awesome. We were able to reproduce it, so let's switch back to Instruments and see what we can find.

I'll quit the application and Instruments automatically stops recording. So, we can see the populated trace data here. And the first thing I'm going to do is make it a little larger so we can see it in more detail.

With the mouse cursor over the track area, a pinch to zoom gesture makes it larger and allows us to see things closer.

On the left-hand side in the track area, we can see several instruments have provided tracks for us. Time Profiler is showing us a summary of the CPU utilization. The Points of Interest Instrument is currently empty. Anand will show you that later. And there are a number of others, including thermal state, and then breakdowns further on down the scroll view.

If we move our mouse cursor over the CPU Usage summary track, we can see a hovering label that shows what the utilization level is.

And when I hit this large area here, the utilization is above 100%. So, this appears to be suspicious and I suspect this is around the time of that reload operation. I'd like to compare this to some of the other tracks. So, we're going to use a feature called Track Pinning. In the left-hand side of the window, when I move my mouse over one of the track entries, a plus button appears.

Clicking it, pins that track to the bottom of the track area. And now we can scroll through the other tracks and see the one that was of interest side by side. You can pin multiple tracks.

As we scroll down, we can see things broken out by each CPU core on the system. And now we have a track entry for the process itself, Solar System Mac. In addition to a CPU usage summary, this also shows us app lifecycle events. We can see here where the application came into the foreground when I clicked it on the dock.

There's also a suspicious red area over here during the CPU usage spike.

Moving the mouse over it, I can see that the label is spinning.

Spinning is how Instruments refers to your main thread being blocked. And on the Mac, that's what causes the Spinning Wait Cursor. The main thread has just a few very specific uses. It should be used for handling user input or for updating the user interface. Clearly, something else is going on here.

I'd like to look at the main thread.

So, I will expand the Solar System Mac process.

And now there are a number of other tracks corresponding to each thread in the application. Scrolling all the way down, here's the main thread. And the main thread is showing a spike. So, this looks like the event that I want to take a look at. The next feature of Instruments that we're going to use allows us to filter events by clicking and dragging in the track area.

Now, the Detail view at the bottom is only showing events from the selected window of time.

Let's look in the Detail view and learn more. The Detail view shows us a call graph. These are all the functions that were invoked during the time of our profile. Or, in this case, during the time we have selected in the filter. It's important to understand what this is doing. We're not actually tracking every function entry and exit. Instead, Time Profiler takes a snapshot many times per second and notes all of the functions that are running in your process.

So, on the left-hand side, we have a wait column.

Solar System Mac appears 100% of the time. This means that in every sample, Solar System Mac was present. That's good, because that's the application that we're profiling.

As we move on down, the main thread is present in 96.7% and so on. And we can begin disclosing these threads to the deeper end of the functions that were called.

But there are a lot of them here and I'd have to click a number of times to find something interesting. So, Instruments provides another useful trick. If you hold down the Option key and click the Disclosure Triangle, Instruments automatically expands the track list until there is a control flow branch, which might be an interesting event. As you can see, there's a lot here, and it can be hard to dig in and find exactly what your problem is. So, Instruments also provides the heaviest stack trace in the Extended Detail View for Time Profiler.

The heaviest stack trace is the set of functions that were called most often during the Profile.

So, up at the top, we can see Solar System Mac appears, and some of these frames are highlighted in white.

These are the frames that are from your own process.

Frames that come from System Frameworks or Libraries are shown in grey.

So, the main thread executes the main function, and then there's a block of System Framework provided functions. It's only further down that we find another area of highlighted functions.

The first one here is labeled as a thunk.

What is a thunk? This is a piece of helper code generated by the compiler. It doesn't correspond directly to any source code in your application. So in this case we'll ignore the thunk. What we want to focus in on is this one, the first closure in a method in the network request scheduler.

If I click on this line, it is selected in the Detail view.

Double clicking it displays the source code right in line.

So, I can see that we have a method called Schedule Parsing Task. And it's doing some work on the main dispatch queue including doing some data parsing, and that seems problematic. As mentioned earlier, the main thread should really only be used for user input and for user interface updates. So, I'd like to fix this. In the top right of the detail view, there's an Open File in Xcode button. I'll click it now.

And Xcode has come to the front.

So, I want to move this on to its own dispatch queue so that it's not blocking the main thread.

The first thing we'll do is we'll create this dispatch queue. We'll call it Parsing Queue. Now, let's move the work onto Parsing Queue by using an asynchronous closure.

We'll just move this work item up there.

And we still want to notify the user interface that parsing completed after that is done. So, we'll take this call onto the dispatch main queue after that. We'll save, and now we're ready to try to reproduce our bug again.

This time, I'll use the Product Menu and select Profile, as Tibet showed you earlier. Xcode builds the application and brings Instruments to the front.

The Template Chooser has appeared again because this time we're not testing a downloaded copy of this application - we're testing the one that Xcode has put in its Drive Data directory.

Time Profiler is selected and we'll click Choose. This time, we don't need to select a target because Xcode has already informed Instruments of the application we want to test.

And furthermore, clicking Record at the top left launches it for us automatically. Switching to the app, let's try the problematic series of user inputs again.

A bunch of clicking and dragging and command + R. And we can see no more Spinning Wait Cursor. Let's do that one more time just to be sure.

Click, drag, command + R. No Spinning Wait Cursor. So, we've addressed our responsiveness issue.

I'll stop recording and we'll pinch to zoom again to expand the track view. I want to make sure that this work has been moved off of the main thread, so I'm going to use the track filter area, top left. And we'll search for the main thread.

The only track that appears is the Solar System Mac's track entry. And when I expand it, I can see the main thread is visible.

Over here, where we have a spike of CPU usage, the main thread is doing relatively little work, and the second time period is showing the same.

So, it appears we have addressed the responsiveness issue and moved this work off of the main thread.

I'd like to discuss a few Profiling tips. First off, Time Profiler is a great tool for understanding how your app is spending time.

This may be a responsiveness issue, like Spinning Wait Cursor. This could also be when your application launches, you want to speed up its launch so that it displays to your users quickly. Use Time Profiler for these cases.

Next, if you have a responsiveness issue, check the main thread. It should really only be used for updating user interface or for handling user input events, like a mouse click on the Mac or a touch on an iOS device.

Third, something I didn't discuss before. You should Profile in Release Mode.

The Compiler supports a number of different optimization levels and when you're doing the Build-Run cycle in Xcode, we use a low-level of optimization to allow that to occur quickly. But this isn't the optimization level that's used when you ship code to your customers using the App Store or Xcode's Archive feature. If you're using Xcode's default configuration, the Profile action in your scheme is set to use Release configuration. However, if you're using custom Compiler flags, be sure that the app you profile is using your Release set of Compiler flags.

Finally, it's important to Profile with difficult workloads or on older devices. In this case, we had a bug that we didn't see at our desk, but customers in the field who had devices with different performance characteristics did encounter it. So, if you have access to those devices, be sure to test on them. As Tibet mentioned earlier, Instruments supports all platforms. We demoed this on the Mac, but it works equally well on iOS, watchOS and tvOS. It also supports the Simulator. But there's an important caveat to understand with the Simulator.

It's running on your Mac. That means that it has your Mac's resource contention.

It has your Mac's CPU and memory performance characteristics. It has your Mac's file system behavior and disc behavior. And it has your Mac's thermal limitations, which are significantly different than that of a smaller embedded device.

Instruments in this case is great for looking at trends. Did something get faster or did it get slower? But it's not going to give you second-by-second accurate simulation of how the application would run. Be sure to test on real hardware before shipping to your customers.

So, we took care of a responsiveness issue, but that's not the whole story. We still have a large spike of CPU usage and it seems like we should be able to reduce that.

CPU usage can drain the battery. It can increase the temperature of a device or on many Macs it'll spin up fans and annoy your users. So, now I'd like to introduce Anand to use the Signpost feature to help dig into the work that our application is doing.

Thank you, Ben.

Good morning, everyone.

I'd like to show you how to use Signpost in your code today to augment the Instruments' traces you collect from it and get a finer understanding of how your code uses system resources.

So, let's begin understanding Signposts by contrasting with what we've been doing so far with Time Profiler.

Time Profiler builds a statistical profile of your code and it does so by observing all the threads in your application at a fixed interval and building the correlation between call stacks and time. But a correlation is no substitute for aa precise measurement which can tell you how or why your code is executing.

There may be a block of code that executes in several short bursts. Or, it might execute in a few longer stretches.

There could be a function which when called on certain arguments can keep the CPU continuously busy.

In order to distinguish these kinds of execution patterns, you need to log precise measurements from your code and that begs the question. What is the best way to log performance measurements from your operations? I'm pleased to tell you that you don't have to worry about printing from your code and teaching Instruments how to read your print statements. Just use Signposts.

Signposts have numerous features that make them ideal for this use case. It is purpose built for logging structured performance data. So, it is simpler and more efficient for this purpose than even printing. It has built-in support for measuring time. So, you don't have to worry about what clock source you're reading from or what time base you're measuring in.

My favorite part is that Instruments already knows how to trace Signposts. In fact, let me give you a sneak preview of an Instruments trace that I collected after adding a Signpost interval to my code. Highlighted is the points of interest track which shows a region of interest that corresponds to a Signpost interval that I added to my code.

So, let me take you to a demo now where I'll resume Ben's investigation of the Solar System application. So, we have the last Instruments trace we were looking at, and we see the familiar region of high CPU utilization. And we'd like to find out why we're using so much CPU time and we'd like to add some Signposts to the code that is using most of the CPU time. Let me take a look at the heavy stack trace.

Last time, Ben started looking from the top of this heavy stack so that we could find out how the code began executing on the main thread.

But this time, I'd like to start looking from the Leaf Level functions to get an idea of what are the most expensive or commonly called functions in this workload.

There's something called Setup Scene over here which appears to be manipulating lots of arrays as a part of this reload operation. And I'd like to find out how much time precisely it is taking. So, let's go to Xcode and take a look at this code. Here's the Setup Scene function, and you can see some vestiges of my previous attempts to log some performance measurements from here. There's a print statement emitting the mock absolute time right at the beginning of the function. And if we scroll all the way to the bottom of the function, there is another Print Statement showing the mock absolute time of when I ended this. But as I previously mentioned, Instruments doesn't know how to read Print Statements. So, we first need to create a log handle that lets us communicate what Instruments. Let's do that.

I created this log handle with a category called Points of Interest. That corresponds to the name of the Points of Interest Instrument.

We'll replace our first Print Statement with a call to an OS Signpost API that begins an interval.

Now, every time you begin an interval you should also end that interval.

Instead of scrolling all the way to the bottom of the function, I'm going to take advantage of Swift Defer Blocks to end the interval. The contents of the Defer Block will be executed at the end of the current scope. Let's build our application with these changes and Profiler in Instruments using the Profile action in the menu.

Let's select the Time Profiler template once again and the target selection area has already been populated by Xcode with a currently built conversion of the Solar System app. Let's start recording.

I'll interact with the app and perform the troublesome sequence of operations again, reload operation.

And we've got some data. So, I'll stop the recording. Let's pinch to zoom into the region of high CPU utilization.

Below the Time Profiler frack, the Points of Interest track now has been populated with the regions of interest that we added in our code. There's a row called Setup Scene corresponding to the name of our Signpost interval, and there are several adjacent regions of interest recorded in the track.

I wasn't expecting many; I was only expecting a few.

I could mouse over each of these and count the number of regions of interest. Or, I could take advantage of the detail view.

So, let me click and drag to select this particular region and then click in the Points of Interest track to repopulate the Detail view with a summary of the Points of Interest track. Taking a closer look, I see that Setup Scene has occurred a total of eight times in this region, and it's averaging about 200 milliseconds for each time it occurs. There are more Detail views available. Let's click on the Jump Bar and select a list of the regions of interest to see a full-time series list of every region of interest that was recorded in this trace. The duration column shows the duration of each of these and I can see that all of these intervals are taking a very similar amount of time to complete, about 210 to 220 milliseconds.

So that's a real headscratcher. Why are we doing a similar amount of work over and over again? Let's look at the caller of Setup Scene to find out if it's being called redundantly for some reason. And the best way to do that is to look at the call graph information recorded by Time Profiler. Let's take advantage of the heavy stack view again at the bottom right-hand corner of the window, and this time I'll look at the caller of Setup Scene, a function called Prepare Scene.

We can double click it to bring up the sources.

And it appears that Prepare Scene called Setup Scene only once. So, this isn't the root cause of our repetition.

To bring back the entire call graph, I'll click on Root in the Jump part and take us to the root of the call graph.

Let's go further up on our quest in the heavy stack. I'll select the next caller and here we see a four loop, which is very plausible cause of the repetition that we're seeing.

Let me bring up this code in Xcode so that we can take a closer look. And I'll use the Jump to File in Xcode button.

Xcode comes up with the four loop displayed.

I remember this function. The purpose of update with planets is to receive the data sent to us by the server, the part of the Reload operation. And then for each planet for which we have new data, update the internal model in the application of each of the planets wherever an update is required.

However, we can receive a blob of data containing updated information for multiple planets, and we appear to be calling Prepare Scene and redrawing the entire view for every single planet that we need to update.

The trace shows us that the cost of redrawing the scene vastly dwarfs the cost of just updating our internal model of the planet. So, the right thing to do here would be to batch up all of our updates to our internal model and just redraw the scene once after we've made all of our updates.

This may seem like a very simple fix but in our experience, we've seen that numerous performance issues of this type can creep into our code as we add new features or fix unrelated bugs. And a great way to prevent such bugs from getting out to our customers is to write tests that routinely exercise their functionality.

To save us some time, I've already written an XC test which exercises the Reload functionality.

If we click on this button to the left of the test, normally it would just run the test. But I will secondary click to reveal the Profile action. This instructs Xcode to build and launch the test under Instruments.

Let's select the Time Profiler template and start recording a trace. In this test, I've placed the Reload operation inside a call to the Measure API. The Measure API runs the workload several times in order to collect several repeated measurements. That can be really helpful for you to learn whether your measurements are repeatable and consistent, or whether there's a lot of run-to-run variation.

It looks like all the repetitions have ended, so I can stop this trace. I'll pinch to zoom into the contents of the points of interest track. And we can see there's an extra row here.

At the very bottom is a Setup Scene interval which I previously added to our code. And above it is another point of interest that is now being contributed to by the Measure API. That tells us the interval corresponding to each iteration that it ran your workload.

Scrolling over this and just eyeballing it, I feel like the workload is behaving pretty consistently from run to run. So, I'd just like to find out what is happening within a single iteration of the test.

Instead of clicking and dragging, there is a nice shortcut for you to select exactly the region corresponding to one event or interval in a track. I'll triple click. This populates the Detail view with information specific to that selection.

And taking a closer look, there appears to be only one call to Setup Scene right now. Let that sink in. We used the information that we gained from Signposts to reduce the amount of CPU time we were using by an order of magnitude.

So, let's review some of the concepts we just encountered. A statistical profile such as that collected by Time Profiler can be really useful to show what code is most commonly executed. But that is not a substitute for a measurement such as that which can be recorded using the Signpost APIs that can show you how and why your code is executed.

We've also seen how it can be really useful to run tests to reliably and repeatedly reproduce our workloads and profile them early and often in our development cycle.

Today, we've largely investigated the kinds of performance issues that arise from high or inappropriately placed CPU utilization. But Instruments has numerous templates which can help answer performance questions about other kinds of resource utilization. We've got a template for file and disc usage.

We've got another template for network utilization. And there's another template that'll help you understand the interaction between your application and the operating system or other processes running on the OS. But that's not all.

Instruments has some really advanced features such as Custom Instruments. If you're a framework author, for instance, and would like your clients of your APIs to be able to answer performance questions about how they're using your framework, then you can provide them with a Custom Instruments package. You could also create Custom Instruments templates, which assemble together a different collection of the Instruments in the Instruments app to help answer a particular performance question.

Coming out of this presentation, I'd really love for you all to start Profiling your code early and often in your development cycle. And please try to out Instruments 11 today. It's packed with some great new features such as Track Pinning and Hierarchical Views which I think will make it really fun to use. We've got comprehensive documentation of the advanced features and certain events workflows of Instruments in our session notes, and there's some great talks from the previous year's conference. Thank you very much. [ Applause ]