Profiling Tools

In the previous lesson (Test Plans and Coverage) we saw that a test entering a line does not say that line is correct. In this lesson we look at code that is correct but slow. If a list cell builds the same formatter from scratch every time it is drawn, the text shown on the screen is correct and the test stays green; but while scrolling, the app does more work than it needs to.

The measurement axis is separation again: we apply the same check to the correct version and to the faulty version. A separating check passes on the correct version and fails on the faulty one. A blind check passes on both. A noisy check fails on both. An inverted check fails on the correct version and passes on the faulty one. We give the core again, because each lesson runs on its own.

// Separation.swift — classifies whether a check tells the correct version from the faulty one
struct Contrast<Output: CustomStringConvertible> {
    let label: String
    let correct: Output
    let faulty: Output
    let passesCorrect: Bool
    let passesFaulty: Bool

    var separation: String {
        switch (passesCorrect, passesFaulty) {
        case (true, false): return "separating"
        case (true, true): return "blind"
        case (false, false): return "noisy"
        case (false, true): return "inverted"
        }
    }

    func describe() -> String {
        let onCorrect = passesCorrect ? "pass" : "fail"
        let onFaulty = passesFaulty ? "pass" : "fail"
        print("\(label) | correct=\(correct)/\(onCorrect) faulty=\(faulty)/\(onFaulty) -> \(separation)")
        return separation
    }
}

func contrast<Output>(_ label: String, correct: Output, faulty: Output, check: (Output) -> Bool) -> Contrast<Output> {
    Contrast(label: label, correct: correct, faulty: faulty, passesCorrect: check(correct), passesFaulty: check(faulty))
}

func countSeparations(_ results: [String]) {
    for name in ["separating", "blind", "noisy", "inverted"] {
        print("\(name): \(results.filter { $0 == name }.count)")
    }
}

Contrast holds the output of the two versions and the check’s verdict on each; the separation label derives from these two verdicts. contrast applies the same closure to both outputs, and countSeparations counts the four categories. The reason for the rule: a check’s value lies not in passing but in telling the two versions apart.

What Profiling Is

Profiling is measuring a running app’s time, memory and rendering work. A test says yes or no to a question; a profiler answers the question “where”. You record a single request, a single scroll or a single screen, and the tool shows the timeline of the recording.

Profiling has two rules. The first is that the measurement is taken with the release configuration; the debug configuration turns off optimizations and distorts the numbers. The second is that the measurement is taken on a physical device where possible; the simulator runs on the desktop processor and does not carry the memory and rendering limits of a physical device.

A profiler offers several timelines. The CPU timeline shows which functions spend time as a call tree; the heaviest call is often the place being sought. The memory timeline tracks allocated objects and their lifetimes. The rendering timeline shows how long each frame takes to prepare. Each timeline answers a different question: the CPU “what is running”, memory “what is accumulating”, rendering “is the screen keeping up”.

Measuring with Signposts

The tool shows the whole app, but the section you are interested in may be small. A signpost is a start and end pair you put in the code; the tool shows this pair on the timeline as a named interval.

// cell drawing signpost — SOURCE
import os

let signposter = OSSignposter(subsystem: "com.example.shop", category: "list")

func configure(cell: PriceCell, price: Decimal) {
    let state = signposter.beginInterval("configure")
    cell.show(price)
    signposter.endInterval("configure", state)
}

This fragment is not run; it has meaning inside the profiler. The interval’s name and category are used as filters on the timeline. The cost of placing a signpost is low, and signposts can be left in the release configuration. The older, function-based form is written with os_signpost; the new form uses the OSSignposter object. Both do the same thing.

Now consider the faulty cell. Building a new formatter on every call is one of the most common slowdowns in a price cell, because a formatter is an expensive object.

// cell configuration — SOURCE
import UIKit

final class PriceCell: UITableViewCell {
    func show(_ price: Decimal) {
        let formatter = NumberFormatter()
        formatter.numberStyle = .currency
        textLabel?.text = formatter.string(from: price as NSDecimalNumber)
    }
}

Every time show(_:) is called it builds a NumberFormatter. While a list is scrolled, hundreds of cells are drawn, so hundreds of formatters are built. The fix is to build the formatter once and share it in every cell.

// cell configuration, fixed — SOURCE
import UIKit

final class PriceCell: UITableViewCell {
    private static let formatter: NumberFormatter = {
        let formatter = NumberFormatter()
        formatter.numberStyle = .currency
        return formatter
    }()

    func show(_ price: Decimal) {
        textLabel?.text = Self.formatter.string(from: price as NSDecimalNumber)
    }
}

The two versions show the same text on the screen. The difference is only in how many times an object is built.

The Work Unit Model

The model below sets up what a profiler measures; it is not the tool itself. We will not measure time: milliseconds vary from machine to machine, and a number printed here would not be repeatable. Instead we count each piece of work as a work unit. Building a formatter is one unit, formatting a price is one unit. With the number of cells the same, the number of objects built determines the work units.

The correct version builds the formatter once and reuses it on every row. The faulty version rebuilds it on every row. Twenty rows are drawn.

// Cells.swift — correct and faulty versions of the price cell, with a work unit counter
struct Rendered {
    let firstRow: String
    let units: Int
}

func formatPrice(_ cents: Int) -> String {
    let rest = cents % 100
    return "\(cents / 100).\(rest < 10 ? "0" : "")\(rest)"
}

func renderRows(count: Int, rebuildsFormatter: Bool) -> Rendered {
    var units = 0
    var first = ""
    if !rebuildsFormatter { units += 1 }
    for row in 1...count {
        if rebuildsFormatter { units += 1 }
        units += 1
        if row == 1 { first = formatPrice(1000 + row * 25) }
    }
    return Rendered(firstRow: first, units: units)
}

renderRows draws twenty rows. In the correct version the formatter is built once (one unit), and then each row spends one unit. In the faulty version each row spends two units. firstRow is the text of the first row; the same price comes out in both versions.

Two checks are applied. The first looks at the drawn text: is the first row 10.25. The second looks at the work unit budget: does the total number of units exceed twenty-five. Twenty-five is this lesson’s rule; it is not a real budget.

// main.swift — drawn text and work unit budget
let correct = renderRows(count: 20, rebuildsFormatter: false)
let faulty = renderRows(count: 20, rebuildsFormatter: true)

let text = contrast("rendered-text", correct: correct.firstRow, faulty: faulty.firstRow, check: { $0 == "10.25" }).describe()
let budget = contrast("work-unit-budget", correct: correct.units, faulty: faulty.units, check: { $0 <= 25 }).describe()

countSeparations([text, budget])

rendered-text | correct=10.25/pass faulty=10.25/pass -> blind
work-unit-budget | correct=21/pass faulty=40/fail -> separating
separating: 1
blind: 1
noisy: 0
inverted: 0

rendered-text is blind: both versions show the same price. work-unit-budget is separating: the correct version spends twenty-one units and fits the budget, the faulty version spends forty units and does not. Forty is almost twice twenty-one, and the difference comes exactly from the formatter rebuilt on every row.

There is an important result here: no test that checks the visible behavior can find this fault. A unit test, a UI test and a coverage threshold all approve this faulty cell. The fault is seen only by a check that looks at the amount of work, or by the profiler’s timeline.

TP1. The model counts building a formatter and formatting a price at the same cost. The real cost ratio was not measured and is not the subject of this lesson; only how many times it is built is counted.

TP2. The model draws twenty rows. As the number of rows grows, the difference between the two versions grows; this lesson’s measure covers only twenty rows.

Reading the Timeline

When a profile recording is opened, there is an order to reading it. First find the interval on the timeline where the slowdown shows; signposts make this easier. Then, within that interval, look at the call tree in the CPU timeline and start from the call that spends the most time. Inverting the call tree, that is, seeing the bottom-most calls at the top, quickly shows the function doing the spending.

In the cell above, the call tree could have shown the NumberFormatter setup among the heavy calls. The tree itself is not a diagnosis of a fault; it says “time is going here”. Understanding why the time goes and deciding whether it is necessary is still the reader’s job.

Another trap in profiling is making the measurement depend on the measuring. The tool slows the app down while recording, and placing signposts too often changes what is measured. So the recording is kept short and a single scenario is measured.

The Bounding Measurement

The work unit budget was a separating check. But the limit of the budget determines the category of the check. Below, the same two versions are checked with three different budgets: twenty-five, fifty and ten.

// main.swift — same counter, three budgets
let correct = renderRows(count: 20, rebuildsFormatter: false)
let faulty = renderRows(count: 20, rebuildsFormatter: true)

let tight = contrast("tight-budget", correct: correct.units, faulty: faulty.units, check: { $0 <= 10 }).describe()
let fitting = contrast("fitting-budget", correct: correct.units, faulty: faulty.units, check: { $0 <= 25 }).describe()
let loose = contrast("loose-budget", correct: correct.units, faulty: faulty.units, check: { $0 <= 50 }).describe()

countSeparations([tight, fitting, loose])

tight-budget | correct=21/fail faulty=40/fail -> noisy
fitting-budget | correct=21/pass faulty=40/fail -> separating
loose-budget | correct=21/pass faulty=40/pass -> blind
separating: 1
blind: 1
noisy: 1
inverted: 0

Ten units is too tight: even the correct version exceeds it and the check becomes noisy. Fifty units is too loose: the faulty version fits as well and the check becomes blind. Only twenty-five stands above the correct version and below the faulty one. The same counter, the same kind of check; only the threshold changed, and the category changed three times.

A budget is itself such a check. The person who sets the budget must measure what the correct version spends; a budget set without measuring is either red from the first day or never red. And as the correct version slows down and approaches the faulty one, the budget’s margin changes too.

TP3. The model’s thresholds are the lesson’s rule. The number for a real budget is found only by measurement, and it is different in every app.

TP4. All three measurements use the same twenty-row drawing. With another number of rows the most suitable budget would be another number.

Common Mistakes

• Profiling in the debug configuration. Because optimizations are off, the numbers mislead.
• Measuring only on the simulator. A physical device has different limits.
• Putting signposts on everything. Signposts fill the timeline and change the work being measured.
• Counting green tests that check the visible output as a performance guarantee.
• Setting the budget by guess, without measuring.

Summary

• Profiling answers the question “where”; a test says yes or no.
• The CPU, memory and rendering timelines correspond to different questions; signposts name the interval you are interested in on the timeline.
• Of two checks, one came out blind and one separating: the drawn text was the same in both versions, the work unit budget passed only on the correct version.
• The same budget check became noisy, separating or blind depending on the threshold; a budget must be set by measuring.
• Tests that look at the visible output cannot find a performance fault.
• This lesson’s separation: separating.

Next Step

Lost time is a performance problem; an object that stays in memory is a separate fault. In the next lesson, Memory Leak Detection will measure, through a retain cycle, an object that is still alive after a screen has closed.