BIGCODE LAB #05: Why does this file take three seconds to compile? — -ftime-trace

TRACK: bigcode | DIFFICULTY: 3 | NEEDS: clang -ftime-trace, jq, a compile command from lab 01

What this teaches

Compile time is a performance problem like any other, with a better instrument than most: clang's -ftime-trace writes a Chrome-trace JSON of every phase, every header parsed, every template instantiated, every function optimized, with durations. Lab 04's profile said "two thirds in libLLVM"; this lab says which passes, on which functions, and which headers and instantiations in the front end.

STEP 1 — Get the trace for a real TU

Take the command from the compile database (lab 01), swap the compiler for clang (this tree was built with g++), add the flags:

$ CMD=$(jq -r '.[] | select(.file | endswith("/lib/Support/APInt.cpp")) | .command' $LLVM_BUILD/compile_commands.json)
$ CMD2=$(echo "$CMD" | sed 's|/usr/lib64/ccache/c++|/usr/bin/clang++|; s| -o [^ ]*| -o /tmp/APInt.o -ftime-trace -ftime-trace-granularity=500 -Wno-unknown-warning-option|')
$ cd $LLVM_BUILD && /usr/bin/time -f "%es %MKB" bash -c "$CMD2"
3.12s 150228KB
$ ls -la /tmp/APInt.json | awk '{print $5" bytes"}'
453906 bytes

-ftime-trace-granularity=N (µs) drops events shorter than N; use 0 to see every header and instantiation (bigger JSON). Open the JSON in chrome://tracing / Perfetto for the flame view; jq for the numbers.

STEP 2 — The phase split

$ jq -r '.traceEvents[] | select(.ph=="X" and (.name|startswith("Total")|not) and .name!="ExecuteCompiler") | "\(.dur/1000|floor) \(.name) \(.args.detail // "")"' /tmp/APInt.json | sort -rn | head -10
2238 Backend
1189 Optimizer
1047 OptModule /home/.../llvm/lib/Support/APInt.cpp
1047 CodeGenPasses
819 Frontend
744 ModuleInlinerWrapperPass [module]
742 ModuleToPostOrderCGSCCPassAdaptor [module]
398 ModuleToFunctionPassAdaptor [module]
107 OptFunction _ZN4llvm8APIntOps26SolveQuadraticEquationWrapENS_5APIntES1_S1_j
57 PerformPendingInstantiations

Read it as a tree: ExecuteCompiler (3.1 s) = Frontend (0.82 s: parse + Sema + IR generation) + Backend (2.24 s) = Optimizer (1.19 s) + CodeGenPasses (1.05 s: instruction selection, register allocation, emission). Inside the optimizer, the inliner and the CGSCC pipeline account for 0.74 s. This matches lab 04's DSO split (71% libLLVM) and refines it: for this -O3 TU, compile time is optimization and codegen, and the front end is a quarter. A "make the build faster" effort on APInt.cpp would look at -O2 vs -O3 for this library, or at the biggest OptFunction entries, not at headers.

$ jq -r '.traceEvents[] | select(.ph=="X" and .name=="OptFunction") | "\(.dur/1000|floor) \(.args.detail)"' /tmp/APInt.json | sort -rn | head -4 | c++filt
107 llvm::APIntOps::SolveQuadraticEquationWrap(llvm::APInt, llvm::APInt, llvm::APInt, unsigned int)
36 llvm::APInt::divide(unsigned long const*, unsigned int, unsigned long const*, unsigned int, unsigned long*, unsigned long*)
30 llvm::APIntOps::GreatestCommonDivisor(llvm::APInt, llvm::APInt)
25 llvm::APInt::sdivrem(llvm::APInt const&, llvm::APInt const&, llvm::APInt&, llvm::APInt&)

One function costs 107 ms of optimizer time: the biggest single item in the file. (Lab 04's flat profile could never have named it; the trace attributes by what the compiler was doing, the profile by which compiler code ran. You need both views.)

STEP 3 — A front-end-bound TU for contrast

The heavy.cpp from lab 04 (a few std::regex / std::map instantiations, -O2):

$ /usr/bin/clang++ -O2 -c heavy.cpp -ftime-trace -ftime-trace-granularity=200 -o /tmp/heavy.o
$ jq -r '... same query ...' heavy.json | sort -rn | head -10
2160 Backend
1368 Optimizer
1014 ModuleInlinerWrapperPass [module]
1003 ModuleToPostOrderCGSCCPassAdaptor [module]
984 Frontend
790 OptModule heavy.cpp
790 CodeGenPasses
473 PerformPendingInstantiations
281 InstantiateFunction std::basic_regex<char>::basic_regex
280 InstantiateFunction std::basic_regex<char>::_M_compile

Half a second of PerformPendingInstantiations, with std::basic_regex alone costing 0.56 s to instantiate, then a 1 s inliner run over the code those instantiations produced. This is what "<regex> is expensive to compile" looks like in numbers, and the fixes are in the source (avoid instantiating it in every TU; explicit instantiation in one; a lighter library), not in the build flags.

What each event kind means (the vocabulary you need)

Aggregating across a build

One TU is a data point; the build is the target. ClangBuildAnalyzer (open source, from the author of -ftime-trace) reads every .json in a build tree and reports the most expensive headers, templates and functions across all TUs. Without it, jq over find build -name '*.json' gives the same totals in a few lines. For GCC the equivalent is -ftime-report (per-TU, text). For Ninja-level attribution (which TUs took longest, wall clock) use ninja -d stats and the .ninja_log (ninjatracing turns it into the same Chrome-trace format).

The procedure

1. Reproduce the one slow TU by hand (ninja -t commands), add -ftime-trace.
2. Phase split first: Frontend vs Backend. That decides which half of this table you are in.
3. Front-end heavy: top Source and Instantiate* entries; fix at the header/template level.
4. Back-end heavy: top OptFunction; check the -O level the TU actually uses (lab 01: all -O3 here); look at the biggest functions and what inlined into them.
5. Prove it: the same command after the change, same machine, same flags, three runs; report seconds and the trace's phase numbers.

Try this yourself

1. Rebuild APInt.cpp with -O2 instead of -O3: how much of the 2.2 s Backend survives? And with -O0?
2. Run with -ftime-trace-granularity=0 and list the ten slowest Source events for heavy.cpp: which header dominates?
3. Add -ftime-report and compare its pass table with the trace's Total <Pass> events.