Reading a Time Profiler trace without guessing

The first ten times I opened Time Profiler I looked at the call tree, saw start_wqthread at 94%, nodded, and closed it. It is an intimidating tool mostly because the default view is close to useless.

Four settings and one habit turned it into the thing I reach for first.

The four checkboxes

In the Call Tree options at the bottom of the window:

• Separate by Thread — on. Otherwise main-thread work and background work are summed together, and the number you care about (is the main thread busy?) is buried.
• Invert Call Tree — on, to start. This puts the functions where time was actually spent at the top, instead of making you walk down from main.
• Hide System Libraries — on. This is the big one. It removes every frame that is not your code, which usually collapses a 40-level tree into something readable.
• Flatten Recursion — on if you have any, off otherwise.

With those four set, the top of the inverted tree is a ranked list of your functions by time spent in them. That is the report you actually wanted.

Read the self time, not the total

The column that matters is self weight — time spent in that function’s own instructions, excluding its callees. Total weight tells you that viewDidLoad accounts for 80% of startup, which is true and useless. Self weight tells you which specific function is burning the cycles.

The workflow I use:

1. Invert the tree, hide system libraries, sort by self weight.
2. Look at the top five entries. That is where the time is.
3. Un-invert and expand from main to see who called the expensive thing, because the fix is often at the call site rather than in the function.

That third step is where the actual insight usually is. A function taking 200ms is a problem; a function taking 2ms called a hundred times from a loop that should have run once is a different problem with a much better fix.

Sampling means it lies about short things

Time Profiler samples the stack every millisecond by default. That has two consequences people trip over.

Anything shorter than the sample interval may not appear at all. A function that runs in 100µs shows up only if it runs often enough to be caught. Absence from the trace is not evidence of speed.

The percentages are of wall time, not CPU time. A thread blocked on a network call or a lock is still being sampled, and the frame it is blocked in accumulates weight. This is why waiting looks like work.

Always profile a Release build

Debug builds have optimisations off. That means no inlining, no specialisation of generics, retain and release calls that would have been elided, and bounds checks that would have been removed.

The result is not “the same but slower”. It is a different performance profile, and I have twice optimised something in Debug that turned out to cost nothing in Release. Profile the configuration you ship.

The same applies to the device. The simulator runs on your Mac’s CPU, which is several times faster than the phone and has completely different memory characteristics. A trace from the simulator tells you about your Mac.

The habit that matters more than the tool

Take a trace before you change anything, and save it.

This sounds obvious and I did not do it for years. Without the baseline you cannot tell whether your change helped, and the temptation is enormous to declare victory because the app “feels” faster after an afternoon of work. Twice now, a change I was certain about turned out to be neutral, and I only knew because I had the before trace to compare against.

Instruments will let you open two traces side by side. Use it.

What it found in my case

The specific thing that prompted me to learn this properly: a list screen that took about 900ms to appear, which I had assumed was network latency.

The inverted tree with system libraries hidden put DateFormatter.string(from:) at the top with 61% self weight. I was creating a formatter inside a map over the response, once per row, and DateFormatter initialisation is famously expensive — it loads locale data every time.

// before: one formatter per row
items.map { ItemViewModel(date: DateFormatter().string(from: $0.date), …) }

// after: one formatter, reused
let formatter = DateFormatter()
formatter.dateStyle = .medium
items.map { ItemViewModel(date: formatter.string(from: $0.date), …) }

900ms to 140ms, from moving one line out of a closure. I would never have guessed it — I was ready to add pagination and a cache to fix a problem that did not exist.

That is the argument for the tool, really. Not that profiling makes you faster at optimising, but that it stops you optimising the wrong thing entirely.