Build time profiling with ClangBuildAnalyzer

[echoix]

I recently learned about ClangBuildAnalyzer, a tool that helps parsing the json files generated by clang's -ftime-trace, contributed by the same author and landed in Clang 9 in Sept 2019. https://aras-p.info/blog/2019/01/16/time-trace-timeline-flame-chart-profiler-for-Clang/

I was curious on what is taking time in our builds on the C/C++ side, if ever there were some optimizations possible.
I built ClangBuildAnalyzer from source with CMake, from the main branch at aras-p/ClangBuildAnalyzer@fc7ff35

I then did:

 ./configure CC=clang CXX=clang++ CFLAGS=-ftime-trace CXXFLAGS=-ftime-trace
build/ClangBuildAnalyzer --start
make # first run I had -j15
build/ClangBuildAnalyzer --stop . clangprofile-linux
build/ClangBuildAnalyzer --analyze clangprofile-linux

Profile files:

• clangprofile-linux
• clangprofile-linux1
• main.json for ./vector/v.in.pdal/OBJ.x86_64-pc-linux-gnu/main.o (second run)

The files that can be individually opened in chrome://tracing are the json files next to the object files. they aren't uploaded here.
There are way less interesting details on object files that weren't C++.

I was using clang 18.1.8:

gitpod /workspace/grass (clangbuildanalyzer) $ clang --version
Ubuntu clang version 18.1.8 (++20240731024944+3b5b5c1ec4a3-1~exp1~20240731145000.144)
Target: x86_64-pc-linux-gnu
Thread model: posix
InstalledDir: /usr/bin

Summary as colored screenshots

From first run:

The json file for v.in.pdal's main.o compilation (one of the longest to parse), opened in chrome://tracing:

Summary as text (first run)

gitpod /workspace/grass (clangbuildanalyzer) $ build/ClangBuildAnalyzer --analyze clangprofile-linux.txt
Analyzing build trace from 'clangprofile-linux.txt'...
**** Time summary:
Compilation (2869 times):
  Parsing (frontend):          698.8 s
  Codegen & opts (backend):     61.6 s

**** Files that took longest to parse (compiler frontend):
 12393 ms: ./raster/r.in.pdal/OBJ.x86_64-pc-linux-gnu/main.o
 10384 ms: ./vector/v.in.pdal/OBJ.x86_64-pc-linux-gnu/main.o
  9093 ms: ./raster/r.in.pdal/OBJ.x86_64-pc-linux-gnu/info.o
  8417 ms: ./raster/r.in.pdal/OBJ.x86_64-pc-linux-gnu/grasslidarfilter.o
  4696 ms: ./raster/r.terraflow/OBJ.x86_64-pc-linux-gnu/fill.o
  4511 ms: ./raster/r.terraflow/OBJ.x86_64-pc-linux-gnu/flow.o
  4094 ms: ./raster/r.viewshed/OBJ.x86_64-pc-linux-gnu/visibility.o
  4090 ms: ./raster/r.terraflow/OBJ.x86_64-pc-linux-gnu/ccforest.o
  4020 ms: ./raster/r.viewshed/OBJ.x86_64-pc-linux-gnu/viewshed.o
  4017 ms: ./raster/r.terraflow/OBJ.x86_64-pc-linux-gnu/main.o

**** Files that took longest to codegen (compiler backend):
  2193 ms: ./lib/gis/OBJ.x86_64-pc-linux-gnu/lz4.o
  1201 ms: ./raster/r.in.pdal/OBJ.x86_64-pc-linux-gnu/main.o
   710 ms: ./raster/r.terraflow/OBJ.x86_64-pc-linux-gnu/ccforest.o
   699 ms: ./raster/r.terraflow/OBJ.x86_64-pc-linux-gnu/fill.o
   503 ms: ./vector/v.in.pdal/OBJ.x86_64-pc-linux-gnu/main.o
   309 ms: ./raster/r.in.pdal/OBJ.x86_64-pc-linux-gnu/info.o
   292 ms: ./lib/external/parson/OBJ.x86_64-pc-linux-gnu/parson.o
   289 ms: ./raster3d/r3.out.v5d/OBJ.x86_64-pc-linux-gnu/v5d.o
   283 ms: ./raster/r.in.pdal/OBJ.x86_64-pc-linux-gnu/grasslidarfilter.o
   214 ms: ./raster/r.viewshed/OBJ.x86_64-pc-linux-gnu/eventlist.o

**** Templates that took longest to instantiate:
  1223 ms: std::__detail::__hyperg<float> (42 times, avg 29 ms)
  1032 ms: std::__detail::__hyperg<long double> (42 times, avg 24 ms)
   949 ms: std::basic_string<char32_t>::_M_construct<const char32_t *> (86 times, avg 11 ms)
   902 ms: std::__detail::__hyperg_reflect<float> (42 times, avg 21 ms)
   899 ms: std::basic_string<char32_t> (43 times, avg 20 ms)
   810 ms: std::__detail::__hyperg_reflect<long double> (42 times, avg 19 ms)
   791 ms: std::operator+<char, std::char_traits<char>, std::allocator<char>> (111 times, avg 7 ms)
   775 ms: std::deque<unsigned long>::insert<std::_Deque_iterator<unsigned long... (4 times, avg 193 ms)
   770 ms: std::deque<unsigned long>::_M_range_insert_aux<std::_Deque_iterator<... (4 times, avg 192 ms)
   671 ms: std::basic_string<char>::_M_construct<char *> (86 times, avg 7 ms)
   660 ms: std::basic_string<char32_t>::basic_string (43 times, avg 15 ms)
   656 ms: std::__detail::__cyl_bessel_i<long double> (42 times, avg 15 ms)
   652 ms: __gnu_cxx::__to_xstring<std::basic_string<wchar_t>, wchar_t> (43 times, avg 15 ms)
   598 ms: __gnu_cxx::__to_xstring<std::basic_string<char>, char> (43 times, avg 13 ms)
   514 ms: std::map<std::basic_string<char>, std::vector<std::shared_ptr<pdal::... (4 times, avg 128 ms)
   490 ms: std::basic_string<char16_t>::_M_construct<const char16_t *> (86 times, avg 5 ms)
   481 ms: std::__detail::__bessel_ik<long double> (42 times, avg 11 ms)
   475 ms: std::_Rb_tree<std::basic_string<char>, std::pair<const std::basic_st... (4 times, avg 118 ms)
   473 ms: std::basic_string<wchar_t>::_M_construct<wchar_t *> (86 times, avg 5 ms)
   470 ms: pdal::ProgramArgs::add<std::basic_string<char>> (4 times, avg 117 ms)
   468 ms: std::__detail::__cyl_bessel_j<float> (42 times, avg 11 ms)
   458 ms: std::basic_string<char> (43 times, avg 10 ms)
   449 ms: std::__detail::__comp_ellint_3<float> (42 times, avg 10 ms)
   444 ms: std::basic_string<wchar_t> (43 times, avg 10 ms)
   442 ms: std::vector<std::unique_ptr<pdal::Arg>>::push_back (4 times, avg 110 ms)
   441 ms: std::vector<std::unique_ptr<pdal::Arg>>::emplace_back<std::unique_pt... (4 times, avg 110 ms)
   441 ms: std::__and_<std::is_convertible<const wchar_t *const &, std::basic_s... (43 times, avg 10 ms)
   436 ms: std::basic_filebuf<char> (30 times, avg 14 ms)
   409 ms: std::basic_string<char16_t> (43 times, avg 9 ms)
   408 ms: std::map<std::basic_string<char>, pdal::Arg *>::operator[] (4 times, avg 102 ms)

**** Template sets that took longest to instantiate:
  4255 ms: std::__and_<$> (944 times, avg 4 ms)
  3325 ms: std::__or_<$> (557 times, avg 5 ms)
  3223 ms: std::unique_ptr<$> (55 times, avg 58 ms)
  2256 ms: std::__detail::__hyperg<$> (84 times, avg 26 ms)
  2211 ms: std::basic_string<$> (172 times, avg 12 ms)
  2105 ms: std::__uniq_ptr_data<$> (55 times, avg 38 ms)
  2097 ms: std::__uniq_ptr_impl<$> (55 times, avg 38 ms)
  1842 ms: std::basic_string<$>::_M_construct<$> (262 times, avg 7 ms)
  1713 ms: std::__detail::__hyperg_reflect<$> (84 times, avg 20 ms)
  1630 ms: std::basic_string<$>::basic_string (217 times, avg 7 ms)
  1587 ms: std::basic_string<$>::_M_construct_aux<$> (262 times, avg 6 ms)
  1576 ms: std::vector<$>::push_back (33 times, avg 47 ms)
  1533 ms: AMI_sort<$> (22 times, avg 69 ms)
  1430 ms: std::is_convertible<$> (460 times, avg 3 ms)
  1266 ms: std::vector<$>::emplace_back<$> (24 times, avg 52 ms)
  1250 ms: __gnu_cxx::__to_xstring<$> (86 times, avg 14 ms)
  1176 ms: std::vector<$>::_M_realloc_insert<$> (33 times, avg 35 ms)
  1153 ms: __gnu_cxx::__stoa<$> (617 times, avg 1 ms)
  1074 ms: std::_Destroy<$> (86 times, avg 12 ms)
  1038 ms: std::is_move_constructible<$> (129 times, avg 8 ms)
  1026 ms: sort<$> (17 times, avg 60 ms)
  1012 ms: std::tuple<$> (59 times, avg 17 ms)
  1006 ms: std::__detail::__cyl_bessel_i<$> (84 times, avg 11 ms)
   898 ms: std::vector<$>::~vector (57 times, avg 15 ms)
   896 ms: std::basic_string_view<$> (172 times, avg 5 ms)
   839 ms: std::__detail::__cyl_bessel_j<$> (84 times, avg 9 ms)
   819 ms: std::__not_<$> (257 times, avg 3 ms)
   802 ms: runFormation<$> (22 times, avg 36 ms)
   791 ms: std::operator+<char, std::char_traits<char>, std::allocator<char>> (111 times, avg 7 ms)
   786 ms: pdal::PointRef::getFieldAs<$> (40 times, avg 19 ms)

**** Functions that took longest to compile:
  5482 ms: main (main.c)
   395 ms: LZ4_compress_fast_extState_fastReset (lz4.c)
   395 ms: LZ4_compress_fast_continue (lz4.c)
   295 ms: LZ4_compress_fast_extState (lz4.c)
   189 ms: main (main.cpp)
   186 ms: print_option (parser_rest_md.c)
   175 ms: read_v5d_header (v5d.c)
   160 ms: bar (bar.c)
   145 ms: get_slot (main.c)
   143 ms: Init (init.c)
   117 ms: input (input.c)
   104 ms: pdal::Dimension::name[abi:cxx11](pdal::Dimension::Id) (main.cpp)
   102 ms: LZ4_compress_destSize_extState (lz4.c)
   101 ms: LZ4_compress_fast_force (lz4.c)
    95 ms: G_define_standard_option (parser_standard_options.c)
    94 ms: init_vars (init_vars.c)
    94 ms: G__usage_html (parser_html.c)
    94 ms: Rast_histogram_eq_fp_colors (color_xform.c)
    93 ms: G_adjust_window_ll (adj_cellhd.c)
    92 ms: Rast_make_wave_colors (color_compat.c)
    92 ms: P_Read_Raster_Region_masked (resamp.c)
    91 ms: main (test_main.c)
    91 ms: check_projection (proj.c)
    91 ms: make_colors (make_colors.c)
    91 ms: Rast__read_null_bits (get_row.c)
    91 ms: G__script (parser_script.c)
    91 ms: do_cum_mfd (do_cum.c)
    91 ms: organize_fp_lookup (color_org.c)
    91 ms: set_params (parameters.c)
    90 ms: LZ4_decompress_safe_forceExtDict (lz4.c)

**** Function sets that took longest to compile / optimize:
   162 ms: void std::__cxx11::basic_string<$>::_M_construct<$>(char const*, cha... (19 times, avg 8 ms)
    95 ms: AMI_STREAM<$>::AMI_STREAM() (26 times, avg 3 ms)
    91 ms: em_pqueue<$>::em_pqueue(MinMaxHeap<$>*, AMI_STREAM<$>*) (3 times, avg 30 ms)
    88 ms: std::_Rb_tree_iterator<$> std::_Rb_tree<$>::_M_insert_<$>(std::_Rb_t... (1 times, avg 88 ms)
    88 ms: std::allocator_traits<$>::deallocate(std::allocator<$>&, pdal::Dimen... (1 times, avg 88 ms)
    86 ms: AMI_STREAM<$>::AMI_STREAM(char const*, AMI_stream_type) (18 times, avg 4 ms)
    86 ms: em_pqueue<$>::merge_streams(AMI_STREAM<$>**, unsigned short, AMI_STR... (3 times, avg 28 ms)
    86 ms: bool pdal::Utils::numericCast<$>(unsigned long, double&) (2 times, avg 43 ms)
    85 ms: AMI_STREAM<$>::~AMI_STREAM() (28 times, avg 3 ms)
    84 ms: EMPQueueAdaptive<$>::initPQ(unsigned long) (3 times, avg 28 ms)
    84 ms: __gnu_cxx::new_allocator<$>::allocate(unsigned long, void const*) (1 times, avg 84 ms)
    84 ms: std::vector<$>::_S_relocate(char*, char*, char*, std::allocator<$>&) (1 times, avg 84 ms)
    80 ms: computeFlowDirections(AMI_STREAM<$>*&, AMI_STREAM<$>*&, AMI_STREAM<$... (1 times, avg 80 ms)
    79 ms: solve_in_memory(AMI_STREAM<$>*, AMI_STREAM<$>*, double, double, IOvi... (1 times, avg 79 ms)
    77 ms: std::_Rb_tree_node<$>* std::_Rb_tree<$>::_M_copy<$>(std::_Rb_tree_no... (2 times, avg 38 ms)
    77 ms: ReplacementHeap<$>::init() (10 times, avg 7 ms)
    76 ms: ReplacementHeapBlock<$>::extract_min() (7 times, avg 10 ms)
    76 ms: em_pqueue<$>::empty_buff(unsigned short) (3 times, avg 25 ms)
    72 ms: em_buffer<$>::cleanup() (1 times, avg 72 ms)
    72 ms: ReplacementHeapBlock<$>::addRun(MEM_STREAM<$>*) (1 times, avg 72 ms)
    72 ms: AMI_STREAM<$>* multiMerge<$>(queue<$>*, keyCmpKeyvalueType<$>*) (1 times, avg 72 ms)
    72 ms: void insertionsort<$>(event_*, unsigned long, RadialCompare&) (1 times, avg 72 ms)
    72 ms: unsigned long makeRun_Block<$>(AMI_STREAM<$>*, event_*, unsigned int... (1 times, avg 72 ms)
    72 ms: std::char_traits<$>::length(char const*) (1 times, avg 72 ms)
    72 ms: std::allocator<$>::~allocator() (1 times, avg 72 ms)
    69 ms: __gnu_cxx::new_allocator<$>::deallocate(std::_Rb_tree_node<$>*, unsi... (1 times, avg 69 ms)
    68 ms: void std::_Function_base::_Base_manager<$>::_M_create<$>(std::_Any_d... (1 times, avg 68 ms)
    68 ms: std::_Rb_tree<std::__cxx11::basic_string<char, std::char_traits<char... (1 times, avg 68 ms)
    64 ms: queue<$>::queue(int) (1 times, avg 64 ms)
    57 ms: void makeRun<$>(AMI_STREAM<$>*, sweepItemBaseType<$>*&, int, PrioCmp... (1 times, avg 57 ms)

**** Expensive headers:
151197 ms: /usr/include/stdlib.h (included 748 times, avg 202 ms), included via:
  670x: <direct include>
  5x: stdlib.h cstdlib 
  5x: stdio.h 
  4x: local_proto.h 
  4x: common.h stdio.h stdlib.h 
  4x: common.h stdlib.h 
  ...

143887 ms: /usr/include/stdio.h (included 1364 times, avg 105 ms), included via:
  571x: <direct include>
  294x: gis.h 
  106x: raster.h gis.h 
  98x: dbmi.h 
  28x: vector.h gis.h 
  16x: ccmath.h 
  ...

108157 ms: /workspace/grass/dist.x86_64-pc-linux-gnu/include/grass/vector.h (included 474 times, avg 228 ms), included via:
  145x: stdlib.h 
  88x: stdio.h 
  31x: string.h 
  29x: <direct include>
  29x: gis.h 
  14x: stdlib.h global.h 
  ...

106664 ms: /workspace/grass/dist.x86_64-pc-linux-gnu/include/grass/gis.h (included 1456 times, avg 73 ms), included via:
  335x: stdlib.h 
  315x: <direct include>
  119x: string.h 
  106x: raster.h 
  70x: math.h 
  41x: stdlib.h vector.h 
  ...

64156 ms: /workspace/grass/dist.x86_64-pc-linux-gnu/include/grass/defs/gis.h (included 2257 times, avg 28 ms), included via:
  406x: stdlib.h 
  353x: stdio.h 
  315x: gis.h 
  131x: string.h 
  106x: raster.h gis.h 
  98x: dbmi.h stdio.h 
  ...

46186 ms: /workspace/grass/dist.x86_64-pc-linux-gnu/include/grass/iostream/ami.h (included 22 times, avg 2099 ms), included via:
  4x: <direct include>
  4x: eventlist.h visibility.h 
  2x: common.h 
  1x: time.h flow.h sweep.h 
  1x: visibility.h 
  1x: viewshed.h visibility.h 
  ...

42856 ms: /usr/include/string.h (included 216 times, avg 198 ms), included via:
  205x: <direct include>
  2x: stdlib.h vector.h dig_structs.h dgl.h rtree.h 
  2x: cstring 
  1x: stdlib.h 
  1x: unistd.h vector.h dig_structs.h dgl.h rtree.h 
  1x: gdal.h cpl_port.h 
  ...

39104 ms: /usr/include/c++/11/iostream (included 41 times, avg 953 ms), included via:
  8x: <direct include>
  5x: common.h 
  4x: eventlist.h visibility.h ami.h ami_stream.h 
  2x: ami.h ami_stream.h assert.h 
  2x: PointTable.hpp SpatialReference.hpp pdal_internal.hpp 
  2x: assert.h 
  ...

38148 ms: /usr/include/math.h (included 936 times, avg 40 ms), included via:
  165x: stdio.h 
  148x: <direct include>
  110x: stdlib.h 
  87x: stdlib.h vector.h dig_structs.h dgl.h ogr_api.h cpl_progress.h cpl_port.h 
  45x: stdio.h vector.h dig_structs.h dgl.h ogr_api.h cpl_progress.h cpl_port.h 
  28x: vector.h gis.h dig_structs.h dgl.h ogr_api.h cpl_progress.h cpl_port.h 
  ...

24352 ms: /workspace/grass/dist.x86_64-pc-linux-gnu/include/grass/iostream/ami_stream.h (included 23 times, avg 1058 ms), included via:
  4x: ami.h 
  4x: eventlist.h visibility.h ami.h 
  2x: common.h ami.h 
  1x: fill.h ami.h 
  1x: viewshed.h visibility.h ami.h 
  1x: ccforest.h ami.h 
  ...

  done in 0.0s.

Summary as text (run 2)

gitpod /workspace/grass (clangbuildanalyzer) $ build/ClangBuildAnalyzer --stop . clangprofile-linux1
Stopping build tracing and saving to 'clangprofile-linux1'...
  done in 0.2s. Run 'ClangBuildAnalyzer --analyze clangprofile-linux1' to analyze it.
gitpod /workspace/grass (clangbuildanalyzer) $ ClangBuildAnalyzer --analyze clangprofile-linux1
bash: ClangBuildAnalyzer: command not found
gitpod /workspace/grass (clangbuildanalyzer) $ build/ClangBuildAnalyzer --analyze clangprofile-linux1
Analyzing build trace from 'clangprofile-linux1'...
**** Time summary:
Compilation (2785 times):
  Parsing (frontend):          112.3 s
  Codegen & opts (backend):     10.4 s

**** Files that took longest to parse (compiler frontend):
  1759 ms: ./vector/v.in.pdal/OBJ.x86_64-pc-linux-gnu/main.o
  1723 ms: ./raster/r.in.pdal/OBJ.x86_64-pc-linux-gnu/main.o
  1657 ms: ./raster/r.in.pdal/OBJ.x86_64-pc-linux-gnu/info.o
  1510 ms: ./raster/r.in.pdal/OBJ.x86_64-pc-linux-gnu/grasslidarfilter.o
   790 ms: ./raster/r.terraflow/OBJ.x86_64-pc-linux-gnu/fill.o
   753 ms: ./raster/r.terraflow/OBJ.x86_64-pc-linux-gnu/water.o
   735 ms: ./imagery/i.atcorr/OBJ.x86_64-pc-linux-gnu/iwave.o
   721 ms: ./raster/r.terraflow/OBJ.x86_64-pc-linux-gnu/ccforest.o
   690 ms: ./raster/r.terraflow/OBJ.x86_64-pc-linux-gnu/sweep.o
   680 ms: ./raster/r.terraflow/OBJ.x86_64-pc-linux-gnu/flow.o

**** Files that took longest to codegen (compiler backend):
   126 ms: ./lib/gis/OBJ.x86_64-pc-linux-gnu/lz4.o
   117 ms: ./raster/r.terraflow/OBJ.x86_64-pc-linux-gnu/water.o
   108 ms: ./raster/r.terraflow/OBJ.x86_64-pc-linux-gnu/ccforest.o
   106 ms: ./raster/r.in.pdal/OBJ.x86_64-pc-linux-gnu/main.o
   102 ms: ./vector/v.in.pdal/OBJ.x86_64-pc-linux-gnu/main.o
   101 ms: ./raster/r.terraflow/OBJ.x86_64-pc-linux-gnu/fill.o
    99 ms: ./raster/r.terraflow/OBJ.x86_64-pc-linux-gnu/sweep.o
    65 ms: ./imagery/i.atcorr/OBJ.x86_64-pc-linux-gnu/iwave.o
    58 ms: ./raster/r.in.pdal/OBJ.x86_64-pc-linux-gnu/info.o
    55 ms: ./raster/r.terraflow/OBJ.x86_64-pc-linux-gnu/plateau.o

**** Templates that took longest to instantiate:
   213 ms: std::__detail::__hyperg<long double> (42 times, avg 5 ms)
   209 ms: std::__detail::__hyperg<float> (42 times, avg 4 ms)
   178 ms: std::basic_string<char16_t>::_M_construct<const char16_t *> (86 times, avg 2 ms)
   172 ms: std::basic_string<char32_t>::_M_construct<const char32_t *> (86 times, avg 2 ms)
   150 ms: __gnu_cxx::__to_xstring<std::basic_string<wchar_t>, wchar_t> (43 times, avg 3 ms)
   147 ms: std::__detail::__hyperg_reflect<long double> (42 times, avg 3 ms)
   145 ms: std::__detail::__hyperg_reflect<float> (42 times, avg 3 ms)
   137 ms: std::basic_string<wchar_t>::_M_construct<wchar_t *> (86 times, avg 1 ms)
   115 ms: std::basic_string<char16_t>::basic_string (43 times, avg 2 ms)
   111 ms: __gnu_cxx::__to_xstring<std::basic_string<char>, char> (43 times, avg 2 ms)
   110 ms: std::basic_string<char32_t>::basic_string (43 times, avg 2 ms)
   106 ms: std::__detail::__cyl_bessel_j<float> (42 times, avg 2 ms)
   106 ms: std::basic_string<char16_t> (43 times, avg 2 ms)
   105 ms: std::basic_string<char32_t> (43 times, avg 2 ms)
   104 ms: std::__detail::__cyl_bessel_j<long double> (42 times, avg 2 ms)
    98 ms: std::operator+<char, std::char_traits<char>, std::allocator<char>> (88 times, avg 1 ms)
    96 ms: std::basic_string<char> (43 times, avg 2 ms)
    93 ms: std::basic_string<wchar_t> (43 times, avg 2 ms)
    93 ms: std::basic_string<wchar_t>::basic_string<wchar_t *, void> (43 times, avg 2 ms)
    92 ms: std::deque<unsigned long>::insert<std::_Deque_iterator<unsigned long... (4 times, avg 23 ms)
    89 ms: std::deque<unsigned long>::_M_range_insert_aux<std::_Deque_iterator<... (4 times, avg 22 ms)
    89 ms: std::basic_string<char16_t>::_M_construct_aux<const char16_t *> (43 times, avg 2 ms)
    88 ms: std::__detail::__cyl_bessel_i<float> (42 times, avg 2 ms)
    86 ms: std::__detail::__cyl_bessel_i<long double> (42 times, avg 2 ms)
    86 ms: std::basic_string<char32_t>::_M_construct_aux<const char32_t *> (43 times, avg 2 ms)
    80 ms: std::__detail::__bessel_jn<float> (42 times, avg 1 ms)
    79 ms: std::map<std::basic_string<char>, std::vector<std::shared_ptr<pdal::... (4 times, avg 19 ms)
    78 ms: std::__detail::__bessel_jn<long double> (42 times, avg 1 ms)
    73 ms: std::basic_string<char>::_M_construct<char *> (86 times, avg 0 ms)
    68 ms: std::basic_string<wchar_t>::_M_construct_aux<wchar_t *> (43 times, avg 1 ms)

**** Template sets that took longest to instantiate:
   637 ms: std::__and_<$> (699 times, avg 0 ms)
   541 ms: std::unique_ptr<$> (55 times, avg 9 ms)
   434 ms: std::__uniq_ptr_data<$> (55 times, avg 7 ms)
   429 ms: std::__uniq_ptr_impl<$> (55 times, avg 7 ms)
   422 ms: std::__detail::__hyperg<$> (84 times, avg 5 ms)
   402 ms: std::basic_string<$> (172 times, avg 2 ms)
   372 ms: AMI_sort<$> (22 times, avg 16 ms)
   360 ms: std::basic_string<$>::_M_construct<$> (262 times, avg 1 ms)
   322 ms: std::basic_string<$>::_M_construct_aux<$> (243 times, avg 1 ms)
   312 ms: std::basic_string<$>::basic_string (212 times, avg 1 ms)
   292 ms: std::__detail::__hyperg_reflect<$> (84 times, avg 3 ms)
   277 ms: sort<$> (16 times, avg 17 ms)
   262 ms: __gnu_cxx::__to_xstring<$> (86 times, avg 3 ms)
   217 ms: std::tuple<$> (59 times, avg 3 ms)
   211 ms: std::__detail::__cyl_bessel_j<$> (84 times, avg 2 ms)
   184 ms: runFormation<$> (22 times, avg 8 ms)
   176 ms: std::basic_string_view<$> (172 times, avg 1 ms)
   175 ms: std::__detail::__cyl_bessel_i<$> (84 times, avg 2 ms)
   168 ms: std::vector<$>::push_back (33 times, avg 5 ms)
   158 ms: std::__detail::__bessel_jn<$> (84 times, avg 1 ms)
   153 ms: makeRun<$> (22 times, avg 6 ms)
   148 ms: std::basic_string<$>::basic_string<$> (96 times, avg 1 ms)
   139 ms: multiMerge<$> (22 times, avg 6 ms)
   135 ms: std::__detail::__bessel_ik<$> (84 times, avg 1 ms)
   130 ms: std::__detail::__riemann_zeta<$> (84 times, avg 1 ms)
   129 ms: std::__detail::__comp_ellint_3<$> (84 times, avg 1 ms)
   128 ms: singleMerge<$> (22 times, avg 5 ms)
   127 ms: std::vector<$> (78 times, avg 1 ms)
   121 ms: std::__detail::__assoc_laguerre<$> (84 times, avg 1 ms)
   120 ms: std::_Destroy<$> (75 times, avg 1 ms)

**** Functions that took longest to compile:
   900 ms: main (main.c)
    22 ms: IWave::print() (iwave.cpp)
    21 ms: c_divr (c_divr.c)
    20 ms: main (main.cpp)
    18 ms: LZ4_compress_fast_extState_fastReset (lz4.c)
    17 ms: draw (draw.c)
    17 ms: LZ4_compress_fast_continue (lz4.c)
    16 ms: pdal::Dimension::name[abi:cxx11](pdal::Dimension::Id) (main.cpp)
    13 ms: close_maps (close_maps.c)
    13 ms: LZ4_compress_fast_extState (lz4.c)
    10 ms: init_vars (init_vars.c)
     9 ms: check_projection (proj.c)
     9 ms: report (report.c)
     8 ms: AerosolModel::print() (aerosolmodel.cpp)
     8 ms: pdal::Dimension::name[abi:cxx11](pdal::Dimension::Id) (grasslidarfilter.cpp)
     7 ms: IWave::aviris(int) (iwave.cpp)
     7 ms: calculate (main.c)
     7 ms: parse (parse.c)
     7 ms: db__driver_fetch (fetch.c)
     7 ms: bar (bar.c)
     7 ms: GeomCond::print() (geomcond.cpp)
     6 ms: do_cum_mfd (do_cum.c)
     6 ms: parse_args (args.c)
     6 ms: print_lasinfo(StringList*) (info.cpp)
     6 ms: pie (pie.c)
     6 ms: print_window (printwindow.c)
     6 ms: print_stats (stats.c)
     6 ms: draw_scale (draw_scale.c)
     6 ms: openfiles (openfiles.c)
     5 ms: read_v5d_header (v5d.c)

**** Function sets that took longest to compile / optimize:
    15 ms: AMI_STREAM<$>::AMI_STREAM() (24 times, avg 0 ms)
    11 ms: em_pqueue<$>::em_pqueue(MinMaxHeap<$>*, AMI_STREAM<$>*) (3 times, avg 3 ms)
    11 ms: AMI_STREAM<$>::AMI_STREAM(char const*, AMI_stream_type) (18 times, avg 0 ms)
    11 ms: ReplacementHeap<$>::ReplacementHeap(unsigned long, queue<$>*) (20 times, avg 0 ms)
     9 ms: em_pqueue<$>::merge_buffer(em_buffer<$>*, AMI_STREAM<$>*, long) (3 times, avg 3 ms)
     7 ms: em_pqueue<$>::merge_streams(AMI_STREAM<$>**, unsigned short, AMI_STR... (3 times, avg 2 ms)
     6 ms: em_buffer<$>::substream_merge(AMI_STREAM<$>**, unsigned int, AMI_STR... (3 times, avg 2 ms)
     6 ms: EMPQueueAdaptive<$>::initPQ(unsigned long) (3 times, avg 2 ms)
     5 ms: solve_in_memory(AMI_STREAM<$>*, AMI_STREAM<$>*, double, double, IOvi... (1 times, avg 5 ms)
     5 ms: double pdal::PointRef::getFieldAs<$>(pdal::Dimension::Id) const (2 times, avg 2 ms)
     4 ms: AMI_STREAM<$>::~AMI_STREAM() (9 times, avg 0 ms)
     4 ms: void std::__cxx11::basic_string<$>::_M_construct<$>(char const*, cha... (8 times, avg 0 ms)
     4 ms: computeFlowDirections(AMI_STREAM<$>*&, AMI_STREAM<$>*&, AMI_STREAM<$... (1 times, avg 4 ms)
     4 ms: em_buffer<$>::em_buffer(unsigned short, unsigned long, unsigned int) (3 times, avg 1 ms)
     3 ms: sweep(AMI_STREAM<$>*, float, int) (1 times, avg 3 ms)
     3 ms: int pdal::PointRef::getFieldAs<$>(pdal::Dimension::Id) const (2 times, avg 1 ms)
     3 ms: distribute_sector(AMI_STREAM<$>*, AMI_STREAM<$>*, double, double, IO... (1 times, avg 3 ms)
     2 ms: em_pqueue<$>::fillpq() (3 times, avg 0 ms)
     2 ms: em_pqueue<$>::empty_buff(unsigned short) (3 times, avg 0 ms)
     2 ms: EMPQueueAdaptive<$>::makeExternal() (3 times, avg 0 ms)
     2 ms: ccforest<$>::findAllRoots(int) (1 times, avg 2 ms)
     2 ms: queue<$>* runFormation<$>(AMI_STREAM<$>*, baseCmpType<$>*) (3 times, avg 0 ms)
     2 ms: std::_Rb_tree_node<$>* std::_Rb_tree<$>::_M_copy<$>(std::_Rb_tree_no... (2 times, avg 1 ms)
     2 ms: AMI_err AMI_sort<$>(AMI_STREAM<$>*, AMI_STREAM<$>**, baseCmpType<$>*... (3 times, avg 0 ms)
     2 ms: em_pqueue<$>::empty_buff_0() (3 times, avg 0 ms)
     2 ms: std::_Rb_tree_node<$>* std::_Rb_tree<$>::_M_copy<$>(std::_Rb_tree_no... (2 times, avg 1 ms)
     2 ms: findPlateaus(AMI_STREAM<$>*, int, int, float, AMI_STREAM<$>*, AMI_ST... (1 times, avg 2 ms)
     1 ms: AMI_STREAM<$>* singleMerge<$>(queue<$>*, baseCmpType<$>*) (3 times, avg 0 ms)
     1 ms: im_buffer<$>::im_buffer(long) (3 times, avg 0 ms)
     1 ms: void std::_Rb_tree<$>::_M_construct_node<$>(std::_Rb_tree_node<$>*, ... (2 times, avg 0 ms)

**** Expensive headers:
23156 ms: /usr/include/stdlib.h (included 724 times, avg 31 ms), included via:
  670x: <direct include>
  5x: stdlib.h cstdlib 
  4x: local_proto.h 
  4x: common.h stdio.h stdlib.h 
  4x: common.h stdlib.h 
  2x: assert.h stdlib.h 
  ...

22710 ms: /usr/include/stdio.h (included 1325 times, avg 17 ms), included via:
  571x: <direct include>
  294x: gis.h 
  106x: raster.h gis.h 
  98x: dbmi.h 
  28x: vector.h gis.h 
  16x: ccmath.h 
  ...

16001 ms: /workspace/grass/dist.x86_64-pc-linux-gnu/include/grass/gis.h (included 1419 times, avg 11 ms), included via:
  332x: stdlib.h 
  315x: <direct include>
  117x: string.h 
  106x: raster.h 
  70x: math.h 
  41x: stdlib.h vector.h 
  ...

15657 ms: /workspace/grass/dist.x86_64-pc-linux-gnu/include/grass/vector.h (included 474 times, avg 33 ms), included via:
  145x: stdlib.h 
  88x: stdio.h 
  31x: string.h 
  29x: <direct include>
  29x: gis.h 
  14x: stdlib.h global.h 
  ...

10222 ms: /workspace/grass/dist.x86_64-pc-linux-gnu/include/grass/defs/gis.h (included 2257 times, avg 4 ms), included via:
  406x: stdlib.h 
  353x: stdio.h 
  315x: gis.h 
  131x: string.h 
  106x: raster.h gis.h 
  98x: dbmi.h stdio.h 
  ...

7945 ms: /workspace/grass/dist.x86_64-pc-linux-gnu/include/grass/iostream/ami.h (included 22 times, avg 361 ms), included via:
  4x: <direct include>
  4x: eventlist.h visibility.h 
  2x: common.h 
  1x: string.h grid.h 
  1x: viewshed.h visibility.h 
  1x: assert.h filldepr.h 
  ...

7090 ms: /usr/include/c++/11/iostream (included 41 times, avg 172 ms), included via:
  8x: <direct include>
  5x: common.h 
  4x: eventlist.h visibility.h ami.h ami_stream.h 
  2x: ami.h ami_stream.h assert.h 
  2x: PointTable.hpp SpatialReference.hpp pdal_internal.hpp 
  2x: assert.h 
  ...

6292 ms: /usr/include/string.h (included 209 times, avg 30 ms), included via:
  205x: <direct include>
  2x: cstring 
  1x: gdal.h cpl_port.h 
  1x: stdio.h freetype.h ftconfig.h 

5997 ms: /usr/include/math.h (included 207 times, avg 28 ms), included via:
  148x: <direct include>
  22x: Gwater.h 
  7x: cmath 
  6x: gis.h Gwater.h 
  5x: stdio.h 
  4x: common.h cmath 
  ...

4481 ms: /workspace/grass/dist.x86_64-pc-linux-gnu/include/grass/iostream/ami_stream.h (included 23 times, avg 194 ms), included via:
  4x: ami.h 
  4x: eventlist.h visibility.h ami.h 
  2x: common.h ami.h 
  1x: fill.h ami.h 
  1x: ccforest.h ami.h 
  1x: viewshed.h visibility.h ami.h 
  ...

  done in 0.0s.

Other interesting reads:

• https://www.figma.com/blog/speeding-up-build-times/
• https://opensource.adobe.com/lagrange-docs/dev/compilation-profiling/
• https://opensource.adobe.com/lagrange-docs/dev/speeding-up-compilation/
• https://trac.webkit.org/wiki/AnalyzingBuildPerformance

[marisn]

C++ takes ages to compile. Colour me surprised.

[wenzeslaus]

I guess the interesting parts are things that are not C++, like LZ4. On the other hand, I would rather pay extra compilation time for parson (also on one of the lists) than glue (and in the future parse) JSON myself, hoping to do better.

[echoix]

I don't think there are really big problems or bottlenecks to solve, but I explored it.
Maybe keep in mind when changing header files that vector.h is included 474 times, and takes 108 seconds to parse, and that grass/gis.h is included 1456 times with about the same time to parse.

What is surprising is the iostream/ami.h is included 22 times, but takes 2/3 of the time of grass/defs/gis.h that is included 2257 times.

[wenzeslaus]

I don't think there are really big problems or bottlenecks to solve...

Yes, that's a good info, too!

Maybe keep in mind when changing header files that vector.h is included 474 times, and takes 108 seconds to parse, and that grass/gis.h is included 1456 times with about the same time to parse.

These are total times spent parsing it for all include statements together, right? I don't know what to take out of that.

What is surprising is the iostream/ami.h is included 22 times, but takes 2/3 of the time of grass/defs/gis.h that is included 2257 times.

iostream/ami.h is C++, no? So no surprise. It should be .hpp or something just to make it clear.