Troubleshot a very slow compiling c file

Introduction

Laymen explanation

As a software programmer, you might have encountered a situation where you thought that compilation is stuck and then later noticed that your assumption was incorrect. Instead, a particular file is taking long time in terms of multiple minutes. Here it is trying to help to troubleshoot such situation

Technical explanation

If you are using gcc compiler, then it provides option to measure compilation time distribution

Using -ftime-report option

A sample of speedy compilation

gcc -ftime-report -c -I. hellofunc.c -o objdir/hellofunc.o

Execution times (seconds)

phase setup : 0.01 (50%) usr 0.00 ( 0%) sys 0.08 (25%) wall 1094 kB (88%) ggc

phase parsing : 0.00 ( 0%) usr 0.00 ( 0%) sys 0.06 (19%) wall 103 kB ( 8%) ggc

phase opt and generate : 0.01 (50%) usr 0.00 ( 0%) sys 0.11 (34%) wall 30 kB ( 2%) ggc

callgraph construction : 0.00 ( 0%) usr 0.00 ( 0%) sys 0.02 ( 6%) wall 2 kB ( 0%) ggc

callgraph optimization : 0.00 ( 0%) usr 0.00 ( 0%) sys 0.06 (19%) wall 1 kB ( 0%) ggc

parser (global) : 0.00 ( 0%) usr 0.00 ( 0%) sys 0.06 (19%) wall 100 kB ( 8%) ggc

tree gimplify : 0.00 ( 0%) usr 0.00 ( 0%) sys 0.01 ( 3%) wall 0 kB ( 0%) ggc

tree SSA other : 0.00 ( 0%) usr 0.00 ( 0%) sys 0.01 ( 3%) wall 0 kB ( 0%) ggc

integrated RA : 0.01 (50%) usr 0.00 ( 0%) sys 0.01 ( 3%) wall 12 kB ( 1%) ggc

TOTAL : 0.02 0.00 0.32 1244 kB

A sample of very slow compilation

gcc -ftime-report -c -I. helloslowfunc.c -o objdir/helloslowfunc.o

Execution times (seconds)

phase parsing : 13.93 ( 1%) usr 10.50 (35%) sys 27.32 ( 1%) wall 517611 kB (28%) ggc

phase lang. deferred : 0.02 ( 0%) usr 0.00 ( 0%) sys 0.02 ( 0%) wall 0 kB ( 0%) ggc

phase opt and generate :2246.76 (99%) usr 19.53 (65%) sys2267.71 (99%) wall 1293776 kB (71%) ggc

phase debug info : 0.00 ( 0%) usr 0.00 ( 0%) sys 0.01 ( 0%) wall 921 kB ( 0%) ggc

phase last asm : 0.49 ( 0%) usr 0.01 ( 0%) sys 1.27 ( 0%) wall 10509 kB ( 1%) ggc

phase finalize : 0.00 ( 0%) usr 0.00 ( 0%) sys 0.04 ( 0%) wall 0 kB ( 0%) ggc

garbage collection : 1.25 ( 0%) usr 0.01 ( 0%) sys 1.25 ( 0%) wall 0 kB ( 0%) ggc

dump files : 0.04 ( 0%) usr 0.05 ( 0%) sys 0.10 ( 0%) wall 0 kB ( 0%) ggc

callgraph construction : 0.41 ( 0%) usr 0.03 ( 0%) sys 0.44 ( 0%) wall 90435 kB ( 5%) ggc

callgraph optimization : 0.06 ( 0%) usr 0.02 ( 0%) sys 0.07 ( 0%) wall 549 kB ( 0%) ggc

ipa inlining heuristics : 0.26 ( 0%) usr 0.01 ( 0%) sys 0.34 ( 0%) wall 4083 kB ( 0%) ggc

ipa reference : 0.02 ( 0%) usr 0.00 ( 0%) sys 0.02 ( 0%) wall 0 kB ( 0%) ggc

ipa pure const : 0.13 ( 0%) usr 0.00 ( 0%) sys 0.15 ( 0%) wall 62 kB ( 0%) ggc

cfg construction : 0.03 ( 0%) usr 0.01 ( 0%) sys 0.02 ( 0%) wall 525 kB ( 0%) ggc

cfg cleanup : 0.28 ( 0%) usr 0.00 ( 0%) sys 0.28 ( 0%) wall 37 kB ( 0%) ggc

trivially dead code : 0.82 ( 0%) usr 0.01 ( 0%) sys 0.77 ( 0%) wall 0 kB ( 0%) ggc

df scan insns : 0.53 ( 0%) usr 0.01 ( 0%) sys 0.51 ( 0%) wall 26 kB ( 0%) ggc

df multiple defs : 0.19 ( 0%) usr 0.01 ( 0%) sys 0.18 ( 0%) wall 0 kB ( 0%) ggc

df reaching defs : 0.77 ( 0%) usr 0.00 ( 0%) sys 0.83 ( 0%) wall 0 kB ( 0%) ggc

df live regs : 1.61 ( 0%) usr 0.00 ( 0%) sys 1.71 ( 0%) wall 13 kB ( 0%) ggc

df live&initialized regs: 0.26 ( 0%) usr 0.01 ( 0%) sys 0.26 ( 0%) wall 0 kB ( 0%) ggc

df use-def / def-use chains: 0.02 ( 0%) usr 0.00 ( 0%) sys 0.01 ( 0%) wall 0 kB ( 0%) ggc

df live reg subwords : 0.07 ( 0%) usr 0.00 ( 0%) sys 0.09 ( 0%) wall 0 kB ( 0%) ggc

df reg dead/unused notes: 1.37 ( 0%) usr 0.00 ( 0%) sys 1.39 ( 0%) wall 9878 kB ( 1%) ggc

register information : 0.21 ( 0%) usr 0.00 ( 0%) sys 0.23 ( 0%) wall 0 kB ( 0%) ggc

alias analysis : 1.68 ( 0%) usr 0.02 ( 0%) sys 1.73 ( 0%) wall 59273 kB ( 3%) ggc

alias stmt walking : 47.57 ( 2%) usr 1.03 ( 3%) sys 48.97 ( 2%) wall 2431 kB ( 0%) ggc

register scan : 0.11 ( 0%) usr 0.00 ( 0%) sys 0.09 ( 0%) wall 639 kB ( 0%) ggc

rebuild jump labels : 0.18 ( 0%) usr 0.00 ( 0%) sys 0.16 ( 0%) wall 0 kB ( 0%) ggc

preprocessing : 4.79 ( 0%) usr 2.81 ( 9%) sys 10.38 ( 0%) wall 298953 kB (16%) ggc

lexical analysis : 4.03 ( 0%) usr 4.80 (16%) sys 9.10 ( 0%) wall 0 kB ( 0%) ggc

parser (global) : 0.51 ( 0%) usr 0.28 ( 1%) sys 0.63 ( 0%) wall 27680 kB ( 2%) ggc

parser struct body : 0.50 ( 0%) usr 0.24 ( 1%) sys 0.66 ( 0%) wall 16052 kB ( 1%) ggc

parser enumerator list : 0.15 ( 0%) usr 0.05 ( 0%) sys 0.18 ( 0%) wall 11230 kB ( 1%) ggc

parser function body : 3.24 ( 0%) usr 2.24 ( 7%) sys 5.65 ( 0%) wall 82671 kB ( 5%) ggc

parser inl. func. body : 0.07 ( 0%) usr 0.03 ( 0%) sys 0.09 ( 0%) wall 2478 kB ( 0%) ggc

inline parameters : 0.31 ( 0%) usr 0.00 ( 0%) sys 0.32 ( 0%) wall 1673 kB ( 0%) ggc

integration : 1.32 ( 0%) usr 0.57 ( 2%) sys 1.91 ( 0%) wall 154004 kB ( 8%) ggc

tree gimplify : 1.28 ( 0%) usr 0.06 ( 0%) sys 1.35 ( 0%) wall 96002 kB ( 5%) ggc

tree eh : 0.06 ( 0%) usr 0.00 ( 0%) sys 0.04 ( 0%) wall 6 kB ( 0%) ggc

tree CFG construction : 0.12 ( 0%) usr 0.02 ( 0%) sys 0.10 ( 0%) wall 13960 kB ( 1%) ggc

tree CFG cleanup : 0.33 ( 0%) usr 0.00 ( 0%) sys 0.40 ( 0%) wall 367 kB ( 0%) ggc

tree copy propagation : 1.93 ( 0%) usr 0.09 ( 0%) sys 1.90 ( 0%) wall 1813 kB ( 0%) ggc

tree PTA : 3.84 ( 0%) usr 0.06 ( 0%) sys 3.93 ( 0%) wall 3752 kB ( 0%) ggc

tree PHI insertion : 0.06 ( 0%) usr 0.01 ( 0%) sys 0.07 ( 0%) wall 4041 kB ( 0%) ggc

tree SSA rewrite : 0.30 ( 0%) usr 0.04 ( 0%) sys 0.31 ( 0%) wall 64170 kB ( 4%) ggc

tree SSA other : 0.37 ( 0%) usr 0.30 ( 1%) sys 0.71 ( 0%) wall 54 kB ( 0%) ggc

tree SSA incremental : 0.15 ( 0%) usr 0.00 ( 0%) sys 0.12 ( 0%) wall 1312 kB ( 0%) ggc

tree operand scan : 1.17 ( 0%) usr 0.92 ( 3%) sys 2.16 ( 0%) wall 52065 kB ( 3%) ggc

dominator optimization : 1.31 ( 0%) usr 0.03 ( 0%) sys 1.38 ( 0%) wall 70288 kB ( 4%) ggc

tree CCP : 16.85 ( 1%) usr 0.31 ( 1%) sys 17.19 ( 1%) wall 3780 kB ( 0%) ggc

tree PHI const/copy prop: 0.02 ( 0%) usr 0.01 ( 0%) sys 0.01 ( 0%) wall 17 kB ( 0%) ggc

tree split crit edges : 0.01 ( 0%) usr 0.00 ( 0%) sys 0.03 ( 0%) wall 6092 kB ( 0%) ggc

tree reassociation : 0.18 ( 0%) usr 0.00 ( 0%) sys 0.18 ( 0%) wall 86 kB ( 0%) ggc

tree FRE : 5.51 ( 0%) usr 0.75 ( 2%) sys 5.92 ( 0%) wall 91408 kB ( 5%) ggc

tree code sinking : 0.08 ( 0%) usr 0.00 ( 0%) sys 0.07 ( 0%) wall 3 kB ( 0%) ggc

tree linearize phis : 0.05 ( 0%) usr 0.00 ( 0%) sys 0.02 ( 0%) wall 7 kB ( 0%) ggc

tree forward propagate : 0.20 ( 0%) usr 0.01 ( 0%) sys 0.18 ( 0%) wall 328 kB ( 0%) ggc

tree phiprop : 0.02 ( 0%) usr 0.00 ( 0%) sys 0.00 ( 0%) wall 0 kB ( 0%) ggc

tree conservative DCE : 0.41 ( 0%) usr 0.15 ( 0%) sys 0.50 ( 0%) wall 4 kB ( 0%) ggc

tree aggressive DCE : 0.28 ( 0%) usr 0.11 ( 0%) sys 0.41 ( 0%) wall 16 kB ( 0%) ggc

tree DSE : 7.78 ( 0%) usr 0.05 ( 0%) sys 7.83 ( 0%) wall 64 kB ( 0%) ggc

PHI merge : 0.00 ( 0%) usr 0.00 ( 0%) sys 0.01 ( 0%) wall 295 kB ( 0%) ggc

tree loop bounds : 0.02 ( 0%) usr 0.00 ( 0%) sys 0.00 ( 0%) wall 98 kB ( 0%) ggc

tree loop invariant motion: 0.12 ( 0%) usr 0.00 ( 0%) sys 0.14 ( 0%) wall 0 kB ( 0%) ggc

tree canonical iv : 0.00 ( 0%) usr 0.00 ( 0%) sys 0.01 ( 0%) wall 157 kB ( 0%) ggc

scev constant prop : 0.01 ( 0%) usr 0.00 ( 0%) sys 0.00 ( 0%) wall 243 kB ( 0%) ggc

complete unrolling : 0.02 ( 0%) usr 0.00 ( 0%) sys 0.00 ( 0%) wall 362 kB ( 0%) ggc

tree iv optimization : 0.15 ( 0%) usr 0.01 ( 0%) sys 0.19 ( 0%) wall 5628 kB ( 0%) ggc

tree copy headers : 0.04 ( 0%) usr 0.01 ( 0%) sys 0.00 ( 0%) wall 694 kB ( 0%) ggc

tree SSA uncprop : 0.01 ( 0%) usr 0.00 ( 0%) sys 0.03 ( 0%) wall 0 kB ( 0%) ggc

tree NRV optimization : 0.01 ( 0%) usr 0.00 ( 0%) sys 0.00 ( 0%) wall 6 kB ( 0%) ggc

tree rename SSA copies : 0.11 ( 0%) usr 0.00 ( 0%) sys 0.09 ( 0%) wall 0 kB ( 0%) ggc

dominance frontiers : 0.04 ( 0%) usr 0.00 ( 0%) sys 0.02 ( 0%) wall 0 kB ( 0%) ggc

dominance computation : 0.46 ( 0%) usr 0.01 ( 0%) sys 0.53 ( 0%) wall 0 kB ( 0%) ggc

out of ssa : 0.22 ( 0%) usr 0.00 ( 0%) sys 0.28 ( 0%) wall 138 kB ( 0%) ggc

expand vars : 0.05 ( 0%) usr 0.00 ( 0%) sys 0.05 ( 0%) wall 9651 kB ( 1%) ggc

expand : 3.06 ( 0%) usr 0.13 ( 0%) sys 3.25 ( 0%) wall 203711 kB (11%) ggc

post expand cleanups : 0.12 ( 0%) usr 0.00 ( 0%) sys 0.14 ( 0%) wall 1309 kB ( 0%) ggc

varconst : 0.00 ( 0%) usr 0.00 ( 0%) sys 0.03 ( 0%) wall 1 kB ( 0%) ggc

lower subreg : 0.28 ( 0%) usr 0.01 ( 0%) sys 0.30 ( 0%) wall 2180 kB ( 0%) ggc

forward prop : 0.98 ( 0%) usr 0.02 ( 0%) sys 1.03 ( 0%) wall 16644 kB ( 1%) ggc

CSE : 9.86 ( 0%) usr 0.07 ( 0%) sys 9.94 ( 0%) wall 12260 kB ( 1%) ggc

dead code elimination : 0.43 ( 0%) usr 0.00 ( 0%) sys 0.42 ( 0%) wall 0 kB ( 0%) ggc

dead store elim1 : 4.84 ( 0%) usr 0.08 ( 0%) sys 4.86 ( 0%) wall 21193 kB ( 1%) ggc

dead store elim2 : 4.19 ( 0%) usr 0.03 ( 0%) sys 4.10 ( 0%) wall 18922 kB ( 1%) ggc

loop init : 0.27 ( 0%) usr 0.02 ( 0%) sys 0.28 ( 0%) wall 2871 kB ( 0%) ggc

loop invariant motion : 0.65 ( 0%) usr 0.01 ( 0%) sys 0.67 ( 0%) wall 4 kB ( 0%) ggc

loop fini : 0.01 ( 0%) usr 0.00 ( 0%) sys 0.01 ( 0%) wall 0 kB ( 0%) ggc

branch prediction : 0.10 ( 0%) usr 0.00 ( 0%) sys 0.13 ( 0%) wall 348 kB ( 0%) ggc

combiner : 1.95 ( 0%) usr 0.05 ( 0%) sys 1.88 ( 0%) wall 11425 kB ( 1%) ggc

if-conversion : 0.07 ( 0%) usr 0.00 ( 0%) sys 0.08 ( 0%) wall 142 kB ( 0%) ggc

integrated RA : 3.26 ( 0%) usr 0.12 ( 0%) sys 3.55 ( 0%) wall 122184 kB ( 7%) ggc

LRA non-specific : 1.26 ( 0%) usr 0.04 ( 0%) sys 1.26 ( 0%) wall 1604 kB ( 0%) ggc

LRA virtuals elimination: 0.03 ( 0%) usr 0.00 ( 0%) sys 0.03 ( 0%) wall 387 kB ( 0%) ggc

LRA reload inheritance : 0.05 ( 0%) usr 0.00 ( 0%) sys 0.02 ( 0%) wall 164 kB ( 0%) ggc

LRA create live ranges : 0.14 ( 0%) usr 0.01 ( 0%) sys 0.16 ( 0%) wall 213 kB ( 0%) ggc

LRA hard reg assignment : 0.08 ( 0%) usr 0.00 ( 0%) sys 0.06 ( 0%) wall 0 kB ( 0%) ggc

LRA coalesce pseudo regs: 0.01 ( 0%) usr 0.00 ( 0%) sys 0.02 ( 0%) wall 0 kB ( 0%) ggc

reload : 0.03 ( 0%) usr 0.00 ( 0%) sys 0.01 ( 0%) wall 0 kB ( 0%) ggc

reload CSE regs : 15.50 ( 1%) usr 0.11 ( 0%) sys 15.60 ( 1%) wall 17079 kB ( 1%) ggc

thread pro- & epilogue : 0.17 ( 0%) usr 0.00 ( 0%) sys 0.14 ( 0%) wall 674 kB ( 0%) ggc

if-conversion 2 : 0.05 ( 0%) usr 0.01 ( 0%) sys 0.03 ( 0%) wall 2 kB ( 0%) ggc

combine stack adjustments: 0.04 ( 0%) usr 0.00 ( 0%) sys 0.04 ( 0%) wall 0 kB ( 0%) ggc

hard reg cprop : 0.52 ( 0%) usr 0.01 ( 0%) sys 0.61 ( 0%) wall 22 kB ( 0%) ggc

machine dep reorg : 0.65 ( 0%) usr 0.00 ( 0%) sys 0.72 ( 0%) wall 16 kB ( 0%) ggc

shorten branches : 0.42 ( 0%) usr 0.00 ( 0%) sys 0.41 ( 0%) wall 0 kB ( 0%) ggc

final : 1.13 ( 0%) usr 0.01 ( 0%) sys 2.16 ( 0%) wall 4728 kB ( 0%) ggc

variable output : 0.03 ( 0%) usr 0.00 ( 0%) sys 0.06 ( 0%) wall 42 kB ( 0%) ggc

symout : 0.91 ( 0%) usr 0.05 ( 0%) sys 1.64 ( 0%) wall 119217 kB ( 7%) ggc

variable tracking : 29.63 ( 1%) usr 0.20 ( 1%) sys 29.84 ( 1%) wall 57211 kB ( 3%) ggc

var-tracking dataflow :1020.23 (45%) usr 6.89 (23%) sys1027.22 (45%) wall 991 kB ( 0%) ggc

var-tracking emit :1041.31 (46%) usr 6.84 (23%) sys1048.25 (46%) wall 5673 kB ( 0%) ggc

tree if-combine : 0.01 ( 0%) usr 0.00 ( 0%) sys 0.02 ( 0%) wall 0 kB ( 0%) ggc

uninit var analysis : 0.01 ( 0%) usr 0.00 ( 0%) sys 0.04 ( 0%) wall 0 kB ( 0%) ggc

straight-line strength reduction: 0.23 ( 0%) usr 0.01 ( 0%) sys 0.24 ( 0%) wall 4117 kB ( 0%) ggc

rest of compilation : 1.24 ( 0%) usr 0.05 ( 0%) sys 1.28 ( 0%) wall 7853 kB ( 0%) ggc

remove unused locals : 0.36 ( 0%) usr 0.00 ( 0%) sys 0.36 ( 0%) wall 0 kB ( 0%) ggc

address taken : 0.20 ( 0%) usr 0.01 ( 0%) sys 0.19 ( 0%) wall 0 kB ( 0%) ggc

unaccounted todo : 0.44 ( 0%) usr 0.07 ( 0%) sys 0.49 ( 0%) wall 0 kB ( 0%) ggc

rebuild frequencies : 0.04 ( 0%) usr 0.00 ( 0%) sys 0.03 ( 0%) wall 0 kB ( 0%) ggc

repair loop structures : 0.03 ( 0%) usr 0.00 ( 0%) sys 0.03 ( 0%) wall 0 kB ( 0%) ggc

TOTAL :2261.20 30.04 2296.41 1823749 kB

===========================

This compilation is taking long time in pre processing stuff. Notice the highlighted text

In case it is found that pre processing is taking long time, we can further troubleshoot by adding -E option.

Reference

http://stackoverflow.com/questions/28919285/identify-slow-to-compile-function

https://gcc.gnu.org/onlinedocs/gcc/Preprocessor-Options.html