Profiling and Benchmarking

The previous lesson showed how a data layout changes the memory cost of a loop, but the lesson assumed one thing: we knew in advance which loop mattered. In a real program this knowledge does not exist. Choosing the place to optimize by guessing is the shortest way to spend effort on a place that does not matter. This lesson explains finding which place is hot by measuring. The question the course measures is the same again: where does a mechanism move the cost? The answer in this lesson is the kind run: profiling is a mechanism paid while the program runs, and the program that runs gives its result. In M10/K03, for the question “how many times did it run”, the count was the measure itself; here the count is a tool of evidence and the lesson is answered with the name of the kind. No time is printed: time depends on the machine and the load, while the hot spot is found from a counter.

Two Methods: Instrumentation and Sampling

A profiler collects data in two ways. Instrumentation is placing counters in the program itself: a counter is incremented at every function entry or at every loop step, and the counters are read when the program ends. The count is exact, because every event is counted; but the counters touch the code, and the measured program is now different from the unmeasured one.

Sampling does not change the code of the program. The profiler stops the program at certain intervals and looks at which function is running at that moment; over enough looks, the function seen most often is the hot spot. The overhead of sampling is smaller, but its result is approximate and depends on timing; the same program gives a slightly different distribution in two runs. In this lesson we do not run sampling, because its output depends on the run; we work with instrumentation, because its output is a count and is the same in every run.

Sampling on a Trace

We can build the model of sampling without tying it to a run. Think of which function is running at each step of the program as a trace: the trace is the sequence of function identifiers in step order. The sampler looks at every period-th step of this trace and counts the identifier it finds. A real sampler does not see the trace; at the moment it stops the program it sees only the current function. Here the trace is known in advance, so we can compute what sampling will find. The trace corresponds to a program that runs one hundred steps of prepare and then 4950 steps of search: 5050 steps in total.

Sampling does two things. It finds the hot spot, because the function that takes longer meets more looks. But it does not give the count exactly: the looks fall on certain points of the trace, and these points depend on the offset. If we sample the same trace starting from step zero or starting from step thirty-five, we get different counts. The hot spot does not change, but the share of the short-running function moves.

// sampling.hpp — a periodic sampling model over a trace
#pragma once
#include <array>
#include <cstddef>
#include <vector>

constexpr int FUNCTION_PREPARE = 0;
constexpr int FUNCTION_SEARCH = 1;

struct SampleCount {
    std::array<int, 2> hits{};
};

inline std::vector<int> build_trace() {
    std::vector<int> trace;
    for (int i = 0; i < 100; ++i) trace.push_back(FUNCTION_PREPARE);
    for (int i = 0; i < 4950; ++i) trace.push_back(FUNCTION_SEARCH);
    return trace;
}

inline SampleCount sample(const std::vector<int>& trace, std::size_t period, std::size_t offset) {
    SampleCount counts;
    for (std::size_t i = offset; i < trace.size(); i += period) ++counts.hits[trace[i]];
    return counts;
}

The period was chosen as seventy. This number is a model parameter; the interval of a real sampler is measured in time and has no counterpart here. When the offset is zero, the looks fall on steps 0, 70, 140, and so on; two looks enter the hundred-step prepare region. When the offset is thirty-five, the looks fall on steps 35, 105, and so on, and only one enters the region. The program that prints the count runs only this computation; the result of the computation is the same in every run, because the trace is fixed and the model has none of the timing noise of real sampling.

Placing Counters

The program below finds the equal pairs among one hundred values. Three operations are counted: prepare, the production of a value; search, the comparison of two values; and dupes, the finding of an equal pair. The counters sit in a Profile structure and are passed to the functions as a parameter; the result is read only when the program ends.

// profile.hpp — counters and the profiled operations
#pragma once
#include <cstddef>
#include <vector>

struct Profile {
    long prepare = 0;
    long search = 0;
    long dupes = 0;
};

inline int prepare_value(Profile& p, int i) {
    ++p.prepare;
    return i % 50;
}

inline int count_dupes(const std::vector<int>& v, Profile& p) {
    int found = 0;
    for (std::size_t i = 0; i < v.size(); ++i) {
        for (std::size_t j = i + 1; j < v.size(); ++j) {
            ++p.search;
            if (v[i] == v[j]) {
                ++p.dupes;
                ++found;
            }
        }
    }
    return found;
}

prepare_value returns i % 50; when one hundred values are produced, each value is found twice. For this reason fifty pairs are expected. count_dupes compares every pair once with two nested loops; for one hundred values the number of pairs is 100 * 99 / 2 = 4950.

Optimizing the Hot Spot: Before and After

The counter pointed at the search operation, but this is only a diagnosis. The value of a diagnosis is that the change made after it can be measured. Finding equal pairs does not require comparing every pair: counting how many times each value occurs in a frequency table and computing c * (c - 1) / 2 for each value gives the same number. Walking one hundred values once is one hundred steps; walking fifty buckets once adds fifty more steps.

To keep the comparison fair, the two versions have the same counter, the same input and the same result type. Here search means “a step of the main loop”: a comparison in the old version, a value read or a bucket sum in the new one. The steps of the two versions are not the same kind of work; for this reason the number compares the operation count of the two versions, not their time.

// optimized.hpp — a second version that gives the same result with a frequency table
#pragma once
#include <algorithm>
#include <vector>

#include "profile.hpp"

inline int count_dupes_table(const std::vector<int>& v, Profile& p) {
    int largest = *std::max_element(v.begin(), v.end());
    std::vector<int> tally(static_cast<std::size_t>(largest) + 1, 0);
    for (int x : v) {
        ++tally[static_cast<std::size_t>(x)];
        ++p.search;
    }
    int found = 0;
    for (int c : tally) {
        found += c * (c - 1) / 2;
        ++p.search;
    }
    return found;
}

The new version walks one hundred values once and fifty buckets once: 150 steps. The old version took 4950 steps. Both versions find fifty pairs; the optimization did not change the result, it only reduced the size of the hot spot. The number compares the operation count of the two versions. Whether the time dropped is another question and is not answered in this lesson.

The Rules of Benchmarking

Profiling says which place inside a program is hot. Benchmarking races two versions against the same question. When done with time, four rules are needed, and none of them is met on its own. The first is warm-up: the first run differs from later runs because it fills the caches and the lazily built structures; the first run should be dropped or reported separately. The second is repetition: a single run depends on the load at that moment; the distribution of many runs should be examined. The third is the same input: if two versions are measured with different inputs, the difference may come from the input too. The fourth is dead code elimination: the standard allows the compiler to delete a computation that does not change observable behavior; a computation whose result is used nowhere may not have run at all while being measured. The fix is to use the result: write it somewhere or print it.

In this lesson we do not print time, but the four rules also apply when measuring with counters. The first three are applied below in a separate measurement program. For the fourth: the result of the count_dupes function above is returned as found and printed, so the computation cannot be deleted.

Where the Measurement Starts

The warm-up rule says that where the measurement starts can change the result. We can show this with a counter too. A table is built at the first query and found ready at later queries. The setup is one hundred steps and each query is ten steps; including the first query in the measurement or not changes the result.

// table.hpp — a table built at the first call and the query steps
#pragma once
#include <vector>

struct LazyTable {
    std::vector<int> values;
    bool ready = false;
};

inline long query(LazyTable& t, int start) {
    long steps = 0;
    if (!t.ready) {
        for (int i = 0; i < 100; ++i) {
            t.values.push_back(i * i);
            ++steps;
        }
        t.ready = true;
    }
    long total = 0;
    for (int k = 0; k < 10; ++k) {
        total += t.values[start + k];
        ++steps;
    }
    (void)total;
    return steps;
}

steps is a local counter: it counts the function’s own steps and starts again from zero at every call. The table is built at the first call with the ready flag; at the second call the flag is set and the setup is skipped.

Applying the Warm-Up Rule with a Counter

Of the four rules, the first three look like this in a measurement program. The same input: in every run query is called with the same start=0 value. Repetition: five runs are made. Warm-up: the first run is reported separately or removed from the average. In every run the table stays in the same object, so the first call does the setup and the later ones do not.

// measure.hpp — repetition, warm-up and the average steps
#pragma once
#include <vector>

#include "table.hpp"

struct WarmupResult {
    long unwarmed = 0;
    long warmed = 0;
    int iterations = 0;
};

inline WarmupResult measure_warmup(int iterations) {
    LazyTable table;
    std::vector<long> steps;
    for (int i = 0; i < iterations; ++i) steps.push_back(query(table, 0));
    long all = 0;
    long without_first = 0;
    for (int i = 0; i < iterations; ++i) {
        all += steps[i];
        if (i > 0) without_first += steps[i];
    }
    WarmupResult result;
    result.iterations = iterations;
    result.unwarmed = all / iterations;
    result.warmed = without_first / (iterations - 1);
    return result;
}

The unwarmed average includes all five runs: (110 + 10 + 10 + 10 + 10) / 5 = 30. The warmed average drops the first run: (10 + 10 + 10 + 10) / 4 = 10. Both numbers are correct, but they measure different things: the first is “what does a program that calls this function five times from scratch pay”, the second is “what is the cost of a query on a ready table”. Giving a number without writing which question it answers is misleading.

Measurement: Which Is the Hot Spot

The program below reads three counters, picks the highest as the hot spot, and queries the table twice.

// profile_measurement.cpp — instrumented profile and a lazily built table
#include <iostream>
#include <vector>

#include "measure.hpp"
#include "optimized.hpp"
#include "profile.hpp"
#include "sampling.hpp"
#include "table.hpp"

int main() {
    Profile p;
    std::vector<int> v;
    for (int i = 0; i < 100; ++i) v.push_back(prepare_value(p, i));
    int found = count_dupes(v, p);
    std::cout << "instrumented profile run prepare=" << p.prepare << " search=" << p.search
              << " dupes=" << p.dupes << "\n";

    const char* hot = "prepare";
    long highest = p.prepare;
    if (p.search > highest) { hot = "search"; highest = p.search; }
    if (p.dupes > highest) { hot = "dupes"; highest = p.dupes; }
    std::cout << "hot spot " << hot << " found=" << found << "\n";

    long increments = p.prepare + p.search + p.dupes;
    std::cout << "instrumentation run increments=" << increments << "\n";

    std::vector<int> trace = build_trace();
    SampleCount zero = sample(trace, 70, 0);
    SampleCount thirty_five = sample(trace, 70, 35);
    std::cout << "sampling run offset=0 prepare=" << zero.hits[FUNCTION_PREPARE]
              << " search=" << zero.hits[FUNCTION_SEARCH] << "\n";
    std::cout << "sampling run offset=35 prepare=" << thirty_five.hits[FUNCTION_PREPARE]
              << " search=" << thirty_five.hits[FUNCTION_SEARCH] << "\n";

    Profile p2;
    int found_table = count_dupes_table(v, p2);
    std::cout << "optimization run before=" << p.search << " after=" << p2.search
              << " found=" << found << "/" << found_table << "\n";

    LazyTable table;
    long first = query(table, 0);
    long second = query(table, 10);
    std::cout << "lazy table run first=" << first << " second=" << second << "\n";

    WarmupResult warmup = measure_warmup(5);
    std::cout << "warm-up run unwarmed=" << warmup.unwarmed
              << " warmed=" << warmup.warmed << " iterations=" << warmup.iterations << "\n";
    return 0;
}

instrumented profile run prepare=100 search=4950 dupes=50
hot spot search found=50
instrumentation run increments=5100
sampling run offset=0 prepare=2 search=71
sampling run offset=35 prepare=1 search=71
optimization run before=4950 after=150 found=50/50
lazy table run first=110 second=10
warm-up run unwarmed=30 warmed=10 iterations=5

CP18. The first line gives the three counters: one hundred values were prepared, 4950 comparisons were made, and 50 equal pairs were found. The hot spot is read from the counter: search is the largest counter and is more than forty-nine times prepare. The place to optimize is the nested loop inside count_dupes; not prepare_value, and not counting the equal pairs. What made this choice is not a guess but the counter.

CP19. The second line prints the number of equal pairs with found=50. Printing the result is also a safeguard against dead code elimination: since the computation is used, the compiler deleting it would have changed observable behavior.

CP20. Sampling with offset zero gave prepare=2 search=71, and with offset thirty-five prepare=1 search=71. In reality one hundred steps are about two percent of 5050 steps, and both runs saw prepare around this share, but a different number of times. In both runs the hot spot is search. What sampling says is the answer to “which is hot”; for the share of small functions it carries a rounding error that depends on the offset.

CP21. The sixth line shows the operation count of the optimization: before=4950, after=150. Both gave found=50; the result did not change. Because before and after depend on the same input and the same counter, the comparison is valid. The number is not time: the two versions take different kinds of steps, and this number is not enough to pass a verdict about time.

CP22. The unwarmed average is 30, the warmed average is 10; both were computed with the same input and five iterations. The source of the difference is a single run: the first run, which did the setup. Five iterations diluted the share of this one run in the average but did not erase it. Repetition does not replace warm-up; the run that does the setup must be named separately.

CP23. The instrumentation itself also did work: the prepare counter was incremented one hundred times, the search counter 4950 times and the dupes counter fifty times; the total is increments=5100. The measured program differs from the unmeasured program by 5100 increments. Since sampling does not change the code, it avoids most of this difference; its price is giving up the exact count.

The Bounding Measurement

The mechanism this lesson measured is finding the hot spot with counters; the lazy table line shows its limit. The same query function counted first=110 steps at the first call and second=10 steps at the second: the setup entered the first measurement and did not enter the second. Comparing the two queries and saying “the second query does eleven times less work” would be wrong; the setup is paid once and then waits ready.

This shows that the result depends on where the measurement starts. If the measurement starts from the first call, the setup of the table is included; if it starts from the second call, it is not. Both results are correct, but they answer different questions. The limit of a profile is this: a counter says whatever it counts; which run you take into the measurement is decided by your own choices. For this reason the starting point is written next to every measurement.

Summary

• The mechanism this lesson measured moves the cost to the kind run: profiling is paid while the program runs and the program that runs gives the result; the measure is a counter, not time.
• Instrumentation places counters in the code and counts exactly but touches the code; sampling does not change the code and has a smaller overhead but its result is approximate.
• The hot spot is found from a counter, not from a guess: instrumented profile found the search counter highest, with 4950, among the three counters.
• Benchmarking asks for the warm-up, repetition, same input and dead code rules; using the result is the safeguard against the last rule.
• lazy table counted the same function at 110 steps at the first call and 10 at the second: where the measurement starts changes the result, so the starting point is written with the measurement.

Next Step

After the profile finds the hot spot, another cost remains: how often the code is rebuilt. The next lesson opens managing compile times: with the question of where the hiding idiom moves what it gains in compiling, we will reduce header dependency.