FForge
← Labsperf-03Measurement●●●○

From "the binary is slow" to the hot LINE of source

perf/03_hot_function.cppneeds: perf record/report/annotate/script,6 steps
0/6 steps
what this lab teaches

The everyday investigation loop on a real (optimized, C++, possibly stripped) binary: sample -> hot SYMBOL -> hot INSTRUCTIONS -> hot SOURCE LINE, and the traps on the way: T1. Inlining: the hot function does not appear in the profile at all, because at -O2 it was inlined into its caller (which was inlined into ITS caller). The samples are charged to whatever symbol is left standing — here, `main`. T2. Mangling: C++ symbols look like _Z9normalizeRKNSt7__cxx11... — you need c++filt (or the tool's -C / --demangle) to read them. T3. Stripped binaries: no symbols -> perf shows raw addresses. You recover names from a separate debug file (.debug + gnu_debuglink), and you learn that perf keeps its own cache of binaries by build-id.

evidence to leave with
Hot lines 119-121 found inside main; inlined frames shown; stripped binary symbolized via .debug file; one address resolved to fnv1a:121
first, get the code
run this
$ git clone https://github.com/adit4443ya/debug_labs.git && cd debug_labs
then build it
run this
$ (cd perf && ./build.sh)   -> bin/03_hot_function (-O2 -g -fno-omit-frame-pointer)
$                                    bin/03_hot_function.stripped + bin/03_hot_function.debug
walk it, one step at a time
run this
$ ../tools/pin.sh -q perf record -o /tmp/03.data ./bin/03_hot_function
what it printed on the machine that wrote this lab
30 passes over 200000 lines: hash=796da7ea odd=3000000
[ perf record: Captured and wrote 0.101 MB /tmp/03.data (2135 samples) ]
run this
$ perf report -i /tmp/03.data --stdio --no-children 2>/dev/null | grep -v '^#' | grep -v '^$' | head -5
what it printed on the machine that wrote this lab
    87.20%  03_hot_function  03_hot_function       [.] main
     4.40%  03_hot_function  libc.so.6             [.] __printf_buffer
     2.07%  03_hot_function  libc.so.6             [.] _itoa_word
     1.81%  03_hot_function  libc.so.6             [.] __printf_buffer_write
     0.79%  03_hot_function  libc.so.6             [.] __memmove_avx_unaligned_erms
TRAP T1: 87% in `main`. Neither `process` nor `fnv1a` appears: clang
inlined fnv1a into process and process into main. If you stopped here
you would "optimize main", which is not an answer. 2135 samples (perf's
default is ~4000/s) is enough; below ~1000 the percentages are noise.
run this
$ perf annotate -i /tmp/03.data --stdio -l -s main 2>/dev/null | sed -n '/Sorted summary/,/Percent/p'
what it printed on the machine that wrote this lab
Sorted summary for file .../perf/bin/03_hot_function
----------------------------------------------
   56.04 03_hot_function.cpp:121
   27.73 03_hot_function.cpp:120
   13.52 03_hot_function.cpp:119
    1.04 stl_iterator.h:1247
    0.61 03_hot_function.cpp:130
`-l` sorts the samples of that symbol by SOURCE LINE (from the -g line
table). Lines 119-121 are the body of fnv1a: the loop, the xor, the
multiply. 97% of main's time is a function that is not in the binary.
And the instructions behind those lines:
run this
$ perf annotate -i /tmp/03.data --stdio -s main 2>/dev/null | awk '$1+0 >= 3.0' | sort -rn | head -8
what it printed on the machine that wrote this lab
   19.89 :   400868:        imull   $0x1000193, %r14d, %r9d
   11.75 :   400848:        imull   $0x1000193, %r14d, %r9d
   10.72 :   400876:        jne     0x400830 <main+0x270>
   10.59 :   400838:        imull   $0x1000193, %r14d, %r9d
   10.46 :   400858:        imull   $0x1000193, %r14d, %r9d
    9.30 :   400855:        xorl    %r9d, %r14d
    7.24 :   40083f:        movzbl  0x1(%r8,%r10), %r14d
    4.07 :   400845:        xorl    %r9d, %r14d
0x1000193 = 16777619 = the FNV prime. The loop was unrolled 4x (four
imull), and the samples cluster on the multiply: a 3-cycle dependent
multiply per byte is the actual bottleneck. That is the answer an
interviewer wants: not "hashing is slow" but "a serial 3-cycle imul per
byte; to go faster hash 4 independent streams or use a wider hash".

The no-disassembly route, straight to lines, across ALL symbols:
run this
$ perf report -i /tmp/03.data --stdio --no-children --sort srcline 2>/dev/null | grep -v '^#' | grep -v '^$' | head -4
what it printed on the machine that wrote this lab
    48.87%  03_hot_function.cpp:121
    24.18%  03_hot_function.cpp:120
    11.79%  03_hot_function.cpp:119
     0.90%  stl_iterator.h:1247
run this
$ ../tools/pin.sh -q perf record -o /tmp/03g.data --call-graph dwarf ./bin/03_hot_function >/dev/null 2>&1
$ perf report -i /tmp/03g.data --stdio --no-children --inline -G 2>/dev/null | grep -v '^#' | grep -v '^$' | head -12
what it printed on the machine that wrote this lab
    87.36%  03_hot_function  03_hot_function       [.] main
            --87.34%--_start
                      __libc_start_main@@GLIBC_2.34
                      __libc_start_call_main
                      main
                       --86.82%--process(std::vector<...> const&, unsigned int*) (inlined)
                                 |--84.09%--fnv1a(char const*, unsigned long) (inlined)
                                 |--0.95%--normalize(std::string const&) (inlined)
`--inline` makes perf print inlined frames (from DWARF) as if they were
calls: now the truth is visible: main > process (inlined) > fnv1a
(inlined) = 84%. Cost: `--call-graph dwarf` copies a chunk of stack per
sample (bigger perf.data, more overhead) but works without frame
pointers. `--call-graph fp` is cheap and needs the binary AND its
libraries built with -fno-omit-frame-pointer (libc here is not).
run this
$ nm -C --defined-only ./bin/03_hot_function | grep -E ' [Tt] ' | grep -E 'process|normalize|fnv1a|main|format'
what it printed on the machine that wrote this lab
00000000004005c0 T main
0000000000400510 T normalize(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)
run this
$ nm --defined-only ./bin/03_hot_function | grep -E ' [Tt] ' | grep -E 'normalize|main'
what it printed on the machine that wrote this lab
00000000004005c0 T main
0000000000400510 T _Z9normalizeRKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE
run this
$ nm --defined-only ./bin/03_hot_function | grep normalize | awk '{print $3}' | c++filt
what it printed on the machine that wrote this lab
normalize(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)
`nm -C` / `llvm-nm -C` / `objdump -C` demangle; `c++filt` demangles
anything piped in. Learn to read the raw form anyway: _Z = mangled,
9normalize = name, R = reference, K = const, NSt7__cxx11... = the
std::string type. Note what is MISSING: no `process`, `fnv1a`, or
`format_summary` symbols at all. They are `static`, used once, and were
inlined, so no out-of-line copy exists. `normalize` survives only because
it has external linkage (the linker might need it) — its inlined copy in
main is what actually runs. That is why STEP 1 could not show them.

The build script produced the "vendor release" shape: objcopy --only-keep-debug bin/03_hot_function bin/03_hot_function.debug strip -o bin/03_hot_function.stripped bin/03_hot_function objcopy --add-gnu-debuglink=bin/03_hot_function.debug bin/03_hot_function.stripped

run this
$ perf buildid-cache -r ./bin/03_hot_function.stripped     # see the NOTE below
$ mv bin/03_hot_function.debug /tmp/                        # pretend we don't have it
$ ../tools/pin.sh -q perf record -o /tmp/03s.data ./bin/03_hot_function.stripped >/dev/null 2>&1
$ perf report -i /tmp/03s.data --stdio --no-children 2>/dev/null | grep -v '^#' | grep -v '^$' | head -3
what it printed on the machine that wrote this lab
    16.26%  03_hot_function  03_hot_function.stripped   [.] 0x0000000000000868
    10.30%  03_hot_function  03_hot_function.stripped   [.] 0x0000000000000855
     9.71%  03_hot_function  03_hot_function.stripped   [.] 0x0000000000000876

No names, only file offsets. This is what a release build from a vendor looks like. Now put the debug file back where the .gnu_debuglink says:

run this
$ readelf -p .gnu_debuglink ./bin/03_hot_function.stripped | grep -o '03_hot_function.debug'
what it printed on the machine that wrote this lab
03_hot_function.debug
run this
$ mv /tmp/03_hot_function.debug bin/ && perf buildid-cache -r ./bin/03_hot_function.stripped
$ perf report -i /tmp/03s.data --stdio --no-children 2>/dev/null | grep -v '^#' | grep -v '^$' | head -3
what it printed on the machine that wrote this lab
    86.31%  03_hot_function  03_hot_function.stripped   [.] main
     4.04%  03_hot_function  libc.so.6                  [.] __printf_buffer
     2.51%  03_hot_function  libc.so.6                  [.] __printf_buffer_write

Same perf.data, names back. perf (and gdb) look for the debuglink file next to the binary, in <dir>/.debug/, in /usr/lib/debug/<path>, and via debuginfod. `perf buildid-cache -a file.debug` registers one explicitly. NOTE (the thing that bit this lab): `perf record` COPIES every binary it samples into ~/.debug/ keyed by build-id, and `strip` preserves the build-id. So after profiling the unstripped binary once, the stripped one "had symbols" for free from the cache. `perf buildid-cache -l` lists it, `-r` forgets it. On a foreign machine that cache is empty.

perf printed file offsets (0x868). The runtime address is in the raw samples: this is a non-PIE binary loaded at 0x400000 (for a PIE the ELF addresses start near 0 and the offset IS the address to symbolize).

run this
$ perf script -i /tmp/03s.data -F ip 2>/dev/null | sort | uniq -c | sort -rn | head -2
what it printed on the machine that wrote this lab
      325            400868
      206            400855
run this
$ llvm-symbolizer --obj=./bin/03_hot_function.debug --inlining --demangle 0x400868
what it printed on the machine that wrote this lab
  fnv1a(char const*, unsigned long)
  /home/.../perf/03_hot_function.cpp:121:11
  process(std::vector<std::__cxx11::basic_string<char, ...>> const&, unsigned int*)
  /home/.../perf/03_hot_function.cpp:143:14
  main
  /home/.../perf/03_hot_function.cpp:163:16
run this
$ addr2line -Cfi -e ./bin/03_hot_function.debug 0x400868
what it printed on the machine that wrote this lab
  process(std::vector<std::__cxx11::basic_string<char, ...> > const&, unsigned int*)
  /home/.../perf/03_hot_function.cpp:121
  main
  /home/.../perf/03_hot_function.cpp:163
  This is the tool behind sanitizer reports and crash symbolication. It
  prints the innermost inlined frame FIRST: fnv1a, line 121 (the multiply),
  inlined into process at line 143, inlined into main at line 163. (Note
  addr2line -i here omits the innermost function NAME but keeps its line;
  llvm-symbolizer is the more precise of the two.) Use this whenever a
  log, a crash dump, or a vendor profile gives you "binary+0x1234".

THE PROCEDURE (memorize; it is the same on Android with simpleperf):
  1. perf record (pinned, representative input, long enough: >1000 samples)
  2. perf report --no-children                -> hot symbols (demangled)
  3. perf annotate -l -s SYM, or --sort srcline -> hot LINES; then the
     hot INSTRUCTIONS, and say WHY they are hot (dependency? miss? branch?)
  4. suspect inlining? --call-graph dwarf + --inline; or a -fno-inline
     diagnostic build (it measures a different program: LOCATE only)
  5. no symbols? debuglink / .debug file / buildid-cache; symbolize addresses
  6. NOW read the source of that line and ask why (labs cache/, codegen/)
the program

a tiny "log processor": builds 200k synthetic lines, then for 30 passes hashes every line (fnv1a: tiny, hot, inlined), normalizes a few fields (medium, out-of-line), and formats a summary (cold). -O2 -g.

take it further

1. Mark fnv1a `__attribute__((noinline))`, rebuild, re-profile: it appears by name. Then check how much slower the program got (call overhead in the hot loop) — the diagnostic build measures a different program. 2. `perf report --sort dso,sym` : how much time is in libc/libstdc++? 3. Hash 4 lines in parallel (4 independent h accumulators) and re-measure. Predict the speedup from "3-cycle dependent imul per byte" first. ============================================================

read the source · perf/03_hot_function.cpp
#include <cstdint> #include <cstdio> #include <cstring> #include <string> #include <vector> /* HOT: tiny, called per line, inlined at -O2. No out-of-line copy exists. */ static inline uint32_t fnv1a(const char *p, size_t n) { uint32_t h = 2166136261u; for (size_t i = 0; i < n; i++) { h ^= (unsigned char)p[i]; h *= 16777619u; } return h; } /* MEDIUM: touched once per line, but only a few bytes. External linkage, so an * out-of-line (mangled) copy exists in the binary for STEP 4. */ uint32_t normalize(const std::string &line) { uint32_t v = 0; for (size_t i = 0; i < line.size() && i < 8; i++) v = v * 10 + (line[i] & 15); return v; } /* COLD: once per pass. */ static void format_summary(char *out, size_t n, uint32_t h, uint64_t cnt) { snprintf(out, n, "hash=%08x odd=%llu", h, (unsigned long long)cnt); } /* The caller that "owns" the samples once fnv1a is inlined. */ static uint64_t process(const std::vector<std::string> &lines, uint32_t *hash_out) { uint32_t h = 0; uint64_t odd = 0; for (const std::string &l : lines) { h ^= fnv1a(l.data(), l.size()); odd += normalize(l) & 1; } *hash_out = h; return odd; } int main(int argc, char **argv) { int passes = argc > 1 ? atoi(argv[1]) : 30; std::vector<std::string> lines; lines.reserve(200000); for (int i = 0; i < 200000; i++) { char buf[96]; snprintf(buf, sizeof buf, "%08d,host%02d,GET /api/v1/items/%d?q=%x,200,%d", i, i % 37, i * 7919, i * 2654435761u, 100 + (i % 900)); lines.emplace_back(buf); } uint32_t h = 0; uint64_t odd = 0; char summary[64]; for (int p = 0; p < passes; p++) { odd += process(lines, &h); format_summary(summary, sizeof summary, h, odd); } printf("%d passes over %zu lines: %s\n", passes, lines.size(), summary); return 0; }
◇
Finish the lab: write the evidence note

A lab is done when you can say what it showed on your machine — not when you have read it.