For the `make buildworld' we log the time spent in each stage (bootstrap tools, building libraries, everything etc), as documented in
https://www.freebsd.org/status/report-2021-07-2021-09/#_current_compilation_time_analysis
It would be great if we have more fine granular statistics based on the subdir targets. It turns out that is pretty easy with a wrapper shell script.
apply this patch and
$ chmod 755 ./tools/build/time-buildworld-*
build the world
$ make buildworld > buildworld.log
# The generated CSV has ca. 2800 lines
$ ./tools/build/time-buildworld-csv.awk buildworld.log > buildworld.csv
output example:
https://people.freebsd.org/~wosch/build-time/buildworld/buildworld.csv
https://people.freebsd.org/~wosch/build-time/buildworld/buildworld.log.gz
The statistics will be generated as CSV, because this is a very simple format and runs on a base system without ports installed.
The columns are: "real", "user", "sys", "start", "end", "exit", "message", "stage"
real: real time in seconds
user: user time used
sys: system time used
start: start time, number of seconds since the Epoch
end: end time, number of seconds since the Epoch
exit: exit status of command(s)
message: the command(s), e.g. sublib lib/libregex
stage: optional, name of stage, e.g. 4.2.4 MACHINE_ARCH=amd64
The overhead for the wrapper script is around 20 CPU seconds, out of 80000 seconds for a fresh full buildworld.
If you dislike this feature or suspect it is causing trouble you can disable it with the variable TIME_ENV=""
Tested on amd64, i386, arm64 and macOS/arm64 cross compiling for ‘buildworld’, and with ‘packages’ and ‘tinderbox’
Notes:
- Do not sum up values, some targets contain other values (recursive subdirs), e.g.
./tools/build/time-buildworld-csv.awk buildworld.log |grep google | awk -F'\t' '{ print $2 "\t" $7}'
63.52 subdir all lib/googletest/gtest
8.16 subdir all lib/googletest/gtest_main
17.97 subdir all lib/googletest/gmock
5.08 subdir all lib/googletest/gmock_main
94.77 subdir all lib/googletest
in this example the subdir “lib/googletest” runs for 94.77 CPU seconds, which is the sum of the subdirs gtest* and gmock*.
- some stages are called twice for machine related stuff (amd64 + i386)
- time is recorded when a stage/subdir is done, not when it started. This can be confusing for parallel builds