Profiling: Measuring Before Optimizing

Part I · Module 25 · Chapter 25.8 · Profiling: Measuring Before Optimizing

1. No External Profiler Works Here

The inventory first, because the rest of the chapter is shaped by it:

sample is the interesting failure, because it looks like it worked. It attaches, prints the process metadata, and then:

Call graph:

Total number in stack (recursive counted multiple, when >=5):

Sort by top of stack, same collapsed (when >= 5):

Three section headers with nothing under them. The reason:

System Integrity Protection status: enabled.

SIP prevents reading another process's stacks, so the sampler collects nothing it can attribute. Codesigning the binary with the get-task-allow entitlement — which fixed the equivalent problem for leaks in Chapter 25.7 §3 — did not fix this one: the report grew from 2,421 to 7,406 bytes and the call graph stayed empty.

So there is no external-profiler output in this chapter, and none should be inferred. What follows uses a profiler built into the program, which works because a process may always sample its own stacks and SIP is therefore not involved.

2. A Profiler You Can Read

Forty lines, and worth understanding rather than treating as a given:

static std::map<void*, long> g_hits;

static void onProf(int, siginfo_t*, void* uc)
{
    auto* c = static_cast<ucontext_t*>(uc);
    void* pc = (void*)c->uc_mcontext->__ss.__pc;     // where the program was
    Dl_info info;
    if (pc && dladdr(pc, &info) && info.dli_saddr) g_hits[info.dli_saddr]++;
}

static void startProfiling(long usec)
{
    struct sigaction sa{};
    sa.sa_flags = SA_SIGINFO | SA_RESTART;
    sa.sa_sigaction = onProf;
    sigaction(SIGPROF, &sa, nullptr);
    struct itimerval t{};
    t.it_interval.tv_usec = usec;  t.it_value.tv_usec = usec;
    setitimer(ITIMER_PROF, &t, nullptr);
}

Four pieces:

ITIMER_PROF fires SIGPROF after a given amount of CPU time, not wall-clock — so time the process spends blocked does not produce samples. That is the right choice for finding compute hot spots and the wrong one for finding I/O waits, which §6 covers.

The signal handler reads the program counter from the interrupted context. That is the whole measurement: a histogram of where the program was when the timer fired.

dladdr maps that address to the enclosing function's start address, and __cxa_demangle turns _Z13transcendentali into transcendental(int) — Chapter 24.5 §3 is the mangling this undoes.

The report divides each function's count by the total, which is what makes the output percentages rather than raw counts.

Two honest limitations of this particular implementation, stated because they bound every number below. It records only the innermost frame, so it is a flat profile with no caller attribution — §4 is why that matters more than it sounds. And the handler touches a std::map, which is not async-signal-safe; it is adequate for a measurement harness and would need a lock-free buffer in anything shipped.

3. One Program, Three Builds, Three Different Answers

The workload calls three functions in a loop: one doing transcendental maths, one doing plain arithmetic, one building strings. Sampling at 1 ms, medians over seven runs with ranges:

-O0:

-O1 -fno-inline:

-O1:

Read the three tables as one result. At -O0, transcendental is the top entry at 36.8% and looks like the thing to optimise. With inlining disabled it falls to 1.4%. At -O1 it does not appear at all, and neither does arithmetic — both were inlined into main, which now holds 16.1%.

Nothing about the program changed. The profile is a property of the build, not of the source.

4. Why the Same Function Went from 36.8% to 1.4%

This is the part that catches people, and it is not noise — the ranges do not overlap, and the explanation is mechanical.

A flat profile attributes a sample to the function that was executing when the timer fired. transcendental spends almost all of its time inside sin, cos and tan, so once those calls are real calls the samples land in libm and transcendental itself shows only the loop overhead. At -O0 the arithmetic around them is unoptimised and bulky enough to catch a third of the samples; at -O1 with inlining disabled it shrinks to almost nothing.

So the three tables are all correct and they answer three different questions:

• -O0 says: where is the program's unoptimised code spending time?
• -O1 -fno-inline says: which functions, as written, hold the time?
• -O1 says: where does the shipped binary spend time?

Only the last one is the question you usually mean, and it is the least readable, because inlining has erased the boundaries you think in. That is the central trade of profiling optimised code and there is no way around it; §5 is how to work with it.

One corollary worth stating: in the -O1 -fno-inline table, arithmetic (12.8%) outranks transcendental (1.4%) — which would read as "the plain arithmetic costs more than the transcendental maths" and is exactly backwards. The transcendental work is real and is attributed to its callees. A flat profile ranks functions by self time, and self time is not cost.

5. How to Run a Profiling Session

Profile the build you ship. -O2 with -g and -fno-omit-frame-pointer, which Chapter 24.7 §4 establishes costs nothing in generated code. Profiling -O0 answers a question about a program nobody runs.

Use a realistic workload, long enough for the sample count to matter. The totals in §3 are a few hundred samples, which is why every row carries a range spanning several points. A profile with fifty samples is a rumour; aim for thousands, which at 1 ms means seconds of CPU time.

Read the aggregate before the top row. §4's callout: the finding was "83% in libm", not "tan is the hot spot".

Get caller attribution before you act. A flat profile cannot tell you which call site is responsible. A real profiler's call graph does; a cheap substitute is to instrument the suspected call sites with scoped timers and compare.

Form a hypothesis with a number in it, then test it — which is Chapter 25.10's whole subject. "Removing the per-sample tan call should remove about 60% of the run time" is testable; "this looks slow" is not.

Re-profile after every change. The profile is a property of the build, and you just changed the build.

6. What a CPU-Time Profile Cannot See

ITIMER_PROF counts CPU time, so a program that is slow because it is waiting produces few samples and no useful attribution. Three cases that matter in this domain:

I/O waits. A model that spends its wall-clock time in write to a log file shows almost no CPU samples. Chapter 22.9 §3's volume arithmetic — 9 GB from per-cycle logging — is the shape of that problem, and the measurement that finds it is wall-clock timing around the I/O, not a CPU profile.

Lock contention. Threads blocked on a mutex are not consuming CPU. A profile shows the lock holder's work and not the waiting, so the symptom is "the profile looks fine and the program is slow". The measurement is contention counters or wall-clock timing per phase.

Memory-bandwidth limits. The CPU is busy and the samples look like ordinary code, but the bottleneck is the memory system. Chapter 20.4's measurement is the archetype: std::find dispatched to a hand-written memchr and was still indistinguishable from a scalar loop, because a 16 MB scan is bandwidth-bound. A profile cannot distinguish that from compute; the way to tell is to shrink the working set and see whether the time falls more than the work does.

The general point: a profile tells you where CPU time goes and nothing about why wall-clock time is larger than CPU time. Measure both. If wall-clock greatly exceeds CPU, the profiler is looking in the wrong place and §7's coarse timing is the right instrument.

7. The Cheap Instruments, Which Are Often Enough

A profiler is not the only measurement and frequently not the first one.

Wall-clock timing around phases answers "which phase" in five minutes, with no tooling:

const auto t0 = Clock::now();
parse(input);
const auto t1 = Clock::now();
simulate(model);
const auto t2 = Clock::now();
report(results);
const auto t3 = Clock::now();
// print three durations

That is a three-bucket profile, it includes I/O and waiting, and on a program nobody has measured before it usually identifies the phase to look at. Chapter 23.1 §7's endl measurement and Chapter 22.9 §2's logging measurement were both found this way.

A counter is often better than a timer. "How many times is this called" and "how many allocations does this do" are deterministic — Chapter 25.9's measurements are counts, not times, and they reproduce exactly where timings on this machine do not. If you suspect a hidden copy, count the copies.

Scoped timers with an asm barrier for a specific hypothesis, which is the bench harness used throughout this curriculum: two warm-ups, a minimum over repetitions, and a median over whole-process runs with the range reported.

And the discipline that makes any of them trustworthy, learned the hard way across this curriculum: a single run is not a figure. Chapter 24.7 §2's non-monotonic warning count and Chapter 24.9 §6's no-op build measuring slower than a four-file rebuild were both single-run artefacts on a loaded machine. Report a median and a range, and if the ordering of your results is impossible, the instrument is wrong before the claim is.

8. The Table

9. What to Actually Do

• Measure before optimising, and measure the build you ship — -O2 -g -fno-omit-frame-pointer.
• Check the platform's profiler actually works before planning around it. Here, sample produces an empty call graph and codesigning does not help.
• Use enough samples. A few hundred gives ranges spanning several percentage points; aim for thousands.
• Read the aggregate, not the top row. The finding in §3 was "83% in libm", not "tan".
• Do not act on self time. Get caller attribution — a call graph, or scoped timers at the suspected call sites.
• Expect your own functions to vanish under inlining, and do not conclude from -O0 what you will do to -O2.
• Compare CPU time against wall-clock time. If wall-clock is much larger, the profiler is the wrong instrument.
• Prefer a counter to a timer where the quantity is deterministic — Chapter 25.9's counts reproduce where timings do not.
• Time phases first. A three-bucket wall-clock profile costs five minutes and usually identifies the phase.
• Report a median and a range. A single run is not a figure, and an impossible ordering means the instrument is broken.

10. Mistakes Worth Making Once

Quoting profiler output from a tool whose call graph was empty. It attaches and reports headers with nothing under them.

Profiling -O0 and optimising -O2. Three builds here gave three different hot spots.

Optimising the top row. tan is the top row; the actionable question is which call sites make the libm calls.

Reading self time as cost. arithmetic outranked transcendental nine to one, backwards.

Concluding a function is cheap because it has few samples. It may be the caller of the expensive thing.

A fifty-sample profile. The ranges in §3 span several points at a few hundred.

Profiling a CPU-time profile for an I/O problem. Waiting produces no samples.

Assuming a memchr-dispatched loop is compute-bound. Chapter 20.4 measured it bandwidth-bound.

Reporting a single run. Two measurements in this curriculum were impossible orderings from one run each.

11. Interview Relevance

The frozen curriculum marks this chapter High, and the question is usually "how do you find a performance problem?" The answer that lands names the order — time the phases with a clock, then profile the phase that dominates, then form a hypothesis with a number in it and test it — rather than starting with a tool.

The measurement worth quoting is the one that makes "profile the build you ship" concrete: the same program under three builds reported three different hot spots, and the function that held 36.8% at -O0 held 1.4% with inlining disabled and did not appear at all at -O1, because it had been inlined into main.

The detail that separates experience from reading is the self-time trap: a flat profile ranks functions by where the instructions are, so the caller of an expensive callee looks cheap — arithmetic outranked transcendental nine to one in one of these profiles, which is exactly backwards. Saying that the finding is the aggregate (83% in libm) rather than the top row shows you have read a profile that was trying to mislead you.

And if the platform comes up, that no external sampling profiler works on this machine — sample attaches and reports an empty call graph under SIP, and codesigning does not fix it — is a concrete reason to verify tooling before relying on it.

12. What You Should Be Able to Say Now

• That no external sampling profiler works here: perf, gprof and instruments are absent, dtrace is SIP-restricted, and sample attaches and reports an empty call graph — which codesigning does not fix.
• That a process may always sample itself, which is why a SIGPROF-based in-program profiler works, and how it is built: an interval timer, the PC from the signal context, dladdr, and __cxa_demangle.
• That ITIMER_PROF measures CPU time, so I/O waits and lock contention produce no samples.
• That the profile is a property of the build: the same program gave transcendental 36.8% at -O0, 1.4% with -fno-inline, and no entry at all at -O1.
• Why: its work happens in sin, cos and tan, and at -O1 it was inlined into main so no instruction belonged to it.
• That a flat profile reports self time, that self time is not cost, and that arithmetic outranking transcendental nine to one is the trap this creates.
• That the finding is the aggregate — 83% in libm — and that you need caller attribution before acting.
• That a CPU profile cannot see I/O, contention or bandwidth limits, and that comparing CPU against wall-clock time is how you detect that.
• That phase timing and counters are cheaper and often sufficient, and that a single run is not a figure.

13. Exercises

Exercise 1 — the platform. Try sample, perf, gprof and instruments on your machine and record what each does. If sample gives you a call graph, your SIP configuration differs — note it.

Exercise 2 — build the profiler. Implement §2's SIGPROF profiler and run it on a program with two functions of known relative cost. Confirm the shares match what you expect.

Exercise 3 — the three builds. Profile one program at -O0, -O1 -fno-inline and -O1, seven runs each, and reproduce the three tables with ranges. Explain each function's movement.

Exercise 4 — the self-time trap. Construct a function whose own body is trivial but which calls something expensive. Confirm it appears near the bottom of a flat profile, then add a cumulative column and watch it move to the top.

Exercise 5 — CPU against wall clock. Write a program that spends most of its wall-clock time in write. Profile it and observe how few samples you get, then measure the phases with a clock instead.

Exercise 6 — the sample count. Run the same profile with a 10 ms interval and a 1 ms interval over the same workload. Compare the ranges across seven runs and decide how many samples you need before you would act.

14. Summary

• No external sampling profiler functions on this machine. perf, gprof and instruments are absent; dtrace is SIP-restricted; and sample attaches and prints an empty call graph because SIP blocks reading another process's stacks — codesigning fixed this for leaks and not for sample. So this chapter shows no external profiler output.
• A process may always sample itself, which makes a SIGPROF + dladdr profiler about forty lines and fully functional. Its limitations are explicit: innermost frame only, so a flat profile, and a handler that is not async-signal-safe.
• The profile is a property of the build, not of the source. The same program: transcendental held 36.8% (31.5–41.9) at -O0, 1.4% (0.7–4.3) with -fno-inline, and did not appear at -O1 — where main held 16.1% because both of my functions had been inlined into it.
• Self time is not cost. transcendental's work happens in sin, cos and tan; in one profile arithmetic outranked it nine to one, which is exactly backwards. A flat profile makes the caller of an expensive callee look cheap.
• So read the aggregate, not the top row. The finding was 83% in libm, which held across all three builds, and the actionable question is which call sites make those calls — which needs caller attribution you do not get from a flat profile.
• Profile the build you ship (-O2 -g -fno-omit-frame-pointer), with thousands of samples, and re-profile after every change.
• A CPU-time profile cannot see I/O waits, lock contention or memory-bandwidth limits. Compare CPU time against wall-clock time to detect that, and Chapter 20.4's bandwidth-bound scan is the archetype.
• Cheaper instruments are often sufficient: wall-clock timing per phase, and counters where the quantity is deterministic — and a single run is never a figure.

Chapter 25.9 is the answer this chapter keeps pointing at: the thing that is actually slow is usually a copy or an allocation the source does not mention, and those are countable rather than timed.