Signal to noise ratio in build systems

Today I will argue why silent rules are a useful feature of good build systems.

Build systems build stuff, mainly by invoking other tools, like compilers, linkers, code generators and file system manipulation tools. Build tools were traditionally printing some indication of progress. Make displays the commands as they are executed. CMake displays a quasi progress bar, including the name of the compiled file and a counter.

Interestingly, it seems the more vertically oriented, the less output shows up by default. If you need to hand-craft a solution out of parts, like with make, debugging the parts is important to the program you are building. Compare the verbosity of a autotools build system with a go build ./... invocation, that can build many thousands of programs and libraries. The former prints walls of text, the latter prints, nothing, unless there's an error.

As an extreme case, this is taken from the build log of Firefox 79. This is the command used to compile a single file. Note that the command is not really verbatim, as the <<PKGBUILDDIR>> parts hide long directory names used internally in the real log (this part is coming from the Debian build system). Also note that despite the length, this is a single line.

/usr/bin/gcc -std=gnu99 -o mpi.o -c -U_FORTIFY_SOURCE -D_FORTIFY_SOURCE=2 -fstack-protector-strong -DNDEBUG=1 -DTRIMMED=1 -DNSS_PKCS11_2_0_COMPAT -DMOZ_HAS_MOZGLUE -DMOZILLA_INTERNAL_API -DIMPL_LIBXUL -DSTATIC_EXPORTABLE_JS_API -I/<<PKGBUILDDIR>>/third_party/prio -I/<<PKGBUILDDIR>>/build-browser/third_party/prio -I/<<PKGBUILDDIR>>/security/nss/lib/freebl/mpi -I/<<PKGBUILDDIR>>/third_party/msgpack/include -I/<<PKGBUILDDIR>>/third_party/prio/include -I/<<PKGBUILDDIR>>/build-browser/dist/include -I/usr/include/nspr -I/usr/include/nss -I/usr/include/nspr -I/<<PKGBUILDDIR>>/build-browser/dist/include/nss -fPIC -include /<<PKGBUILDDIR>>/build-browser/mozilla-config.h -DMOZILLA_CLIENT -Wdate-time -D_FORTIFY_SOURCE=2 -O2 -fdebug-prefix-map=/<<PKGBUILDDIR>>=. -fstack-protector-strong -Wformat -Werror=format-security -fno-strict-aliasing -ffunction-sections -fdata-sections -fno-math-errno -pthread -pipe -g -freorder-blocks -O2 -fomit-frame-pointer -funwind-tables -Wall -Wempty-body -Wignored-qualifiers -Wpointer-arith -Wsign-compare -Wtype-limits -Wunreachable-code -Wduplicated-cond -Wno-error=maybe-uninitialized -Wno-error=deprecated-declarations -Wno-error=array-bounds -Wno-error=coverage-mismatch -Wno-error=free-nonheap-object -Wno-multistatement-macros -Wno-error=class-memaccess -Wno-error=deprecated-copy -Wformat -Wformat-overflow=2 -MD -MP -MF .deps/mpi.o.pp /<<PKGBUILDDIR>>/security/nss/lib/freebl/mpi/mpi.c

This particular build log is 299738 lines long. That's about 40MB of text output, for a single build.

Obvously, not all builds are alike. There is value in an overly verbose log, like this one, because when something fails the log may be all you get. It is useful to be able to repeat the exact steps taken to see the failure in order to fix it.

On the other end of the spectrum you can look at incremental builds, performed locally while editing the source. There some things are notable:

• The initial build is much like the one quoted above, except that the log file will not be looked at by hand. An IDE may parse it to pick up warnings or errors. Many developers don't use IDEs and just run the build and ignore the wall of text it produces, as long as it doesn't fail entirely.

• As code is changed, the build system will re-compile the parts that became invalidated by the changes. This can be as little as one .c file or as many as all the .c files, that include a common header that was changed. Interestingly computing the number of files that need changes may take a while and it may be faster to fire start compiling even before the whole set is known. Having a precise progress bar may be detrimental to the performance.

• The output of the compiler may be more important than the invocation of the compiler. After all, it's very easy to invoke the build system again. Reading a page-long argument list to gcc is less relevant than the printed error or warning.

That last point is what I want to focus on. The whole idea is to hide or simplify some information, in order to present other kind of information more prominently. We attenunate the build command to amplify the compiler output.

Compare those two make check output logs from my toy library. I'm working on a few new manual pages and I have a rule which uses man to verify syntax. Note that I specifically used markup that wraps long lines, as this is also something you'd see in a terminal window.

This is what you get out of the box:

zyga@x240 ~/D/libzt (feature/defer)> make check
/usr/bin/shellcheck configure
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/ZT_CMP_BOOL.3 2>&1 >/dev/null | sed -e 's@tbl:@man/ZT_CMP_BOOL.3@g'
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/ZT_CMP_INT.3 2>&1 >/dev/null | sed -e 's@tbl:@man/ZT_CMP_INT.3@g'
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/ZT_CMP_PTR.3 2>&1 >/dev/null | sed -e 's@tbl:@man/ZT_CMP_PTR.3@g'
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/ZT_CMP_RUNE.3 2>&1 >/dev/null | sed -e 's@tbl:@man/ZT_CMP_RUNE.3@g'
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/ZT_CMP_UINT.3 2>&1 >/dev/null | sed -e 's@tbl:@man/ZT_CMP_UINT.3@g'
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/ZT_CURRENT_LOCATION.3 2>&1 >/dev/null | sed -e 's@tbl:@man/ZT_CURRENT_LOCATION.3@g'
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/ZT_FALSE.3 2>&1 >/dev/null | sed -e 's@tbl:@man/ZT_FALSE.3@g'
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/ZT_NOT_NULL.3 2>&1 >/dev/null | sed -e 's@tbl:@man/ZT_NOT_NULL.3@g'
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/ZT_NULL.3 2>&1 >/dev/null | sed -e 's@tbl:@man/ZT_NULL.3@g'
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/ZT_TRUE.3 2>&1 >/dev/null | sed -e 's@tbl:@man/ZT_TRUE.3@g'
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/libzt-test.1 2>&1 >/dev/null | sed -e 's@tbl:@man/libzt-test.1@g'
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/libzt.3 2>&1 >/dev/null | sed -e 's@tbl:@man/libzt.3@g'
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/zt_check.3 2>&1 >/dev/null | sed -e 's@tbl:@man/zt_check.3@g'
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/zt_claim.3 2>&1 >/dev/null | sed -e 's@tbl:@man/zt_claim.3@g'
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/zt_closure.3 2>&1 >/dev/null | sed -e 's@tbl:@man/zt_closure.3@g'
mdoc warning: A .Bd directive has no matching .Ed (#20)
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/zt_closure_func0.3 2>&1 >/dev/null | sed -e 's@tbl:@man/zt_closure_func0.3@g'
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/zt_closure_func1.3 2>&1 >/dev/null | sed -e 's@tbl:@man/zt_closure_func1.3@g'
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/zt_defer.3 2>&1 >/dev/null | sed -e 's@tbl:@man/zt_defer.3@g'
Usage: .Fn function_name [function_arg] ... (#16)
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/zt_location.3 2>&1 >/dev/null | sed -e 's@tbl:@man/zt_location.3@g'
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/zt_location_at.3 2>&1 >/dev/null | sed -e 's@tbl:@man/zt_location_at.3@g'
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/zt_main.3 2>&1 >/dev/null | sed -e 's@tbl:@man/zt_main.3@g'
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/zt_pack_boolean.3 2>&1 >/dev/null | sed -e 's@tbl:@man/zt_pack_boolean.3@g'
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/zt_pack_closure0.3 2>&1 >/dev/null | sed -e 's@tbl:@man/zt_pack_closure0.3@g'
mdoc warning: A .Bd directive has no matching .Ed (#20)
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/zt_pack_closure1.3 2>&1 >/dev/null | sed -e 's@tbl:@man/zt_pack_closure1.3@g'
mdoc warning: A .Bd directive has no matching .Ed (#21)
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/zt_pack_integer.3 2>&1 >/dev/null | sed -e 's@tbl:@man/zt_pack_integer.3@g'
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/zt_pack_nothing.3 2>&1 >/dev/null | sed -e 's@tbl:@man/zt_pack_nothing.3@g'
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/zt_pack_pointer.3 2>&1 >/dev/null | sed -e 's@tbl:@man/zt_pack_pointer.3@g'
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/zt_pack_rune.3 2>&1 >/dev/null | sed -e 's@tbl:@man/zt_pack_rune.3@g'
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/zt_pack_string.3 2>&1 >/dev/null | sed -e 's@tbl:@man/zt_pack_string.3@g'
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/zt_pack_unsigned.3 2>&1 >/dev/null | sed -e 's@tbl:@man/zt_pack_unsigned.3@g'
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/zt_test.3 2>&1 >/dev/null | sed -e 's@tbl:@man/zt_test.3@g'
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/zt_test_case_func.3 2>&1 >/dev/null | sed -e 's@tbl:@man/zt_test_case_func.3@g'
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/zt_test_suite_func.3 2>&1 >/dev/null | sed -e 's@tbl:@man/zt_test_suite_func.3@g'
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/zt_value.3 2>&1 >/dev/null | sed -e 's@tbl:@man/zt_value.3@g'
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/zt_visit_test_case.3 2>&1 >/dev/null | sed -e 's@tbl:@man/zt_visit_test_case.3@g'
LC_ALL=C MANROFFSEQ= MANWIDTH=80 man --warnings=all --encoding=UTF-8 --troff-device=utf8 --ditroff --local-file man/zt_visitor.3 2>&1 >/dev/null | sed -e 's@tbl:@man/zt_visitor.3@g'
plog-converter --settings ./.pvs-studio.cfg -d V1042 --srcRoot . --renderTypes errorfile zt.c.PVS-Studio.log zt-test.c.PVS-Studio.log | srcdir=. abssrcdir=/home/zyga/Dokumenty/libzt awk -f /usr/local/include/zmk/pvs-filter.awk
./libzt-test
libzt self-test successful

This is what you get when you use ./configure --enable-silent-rules:

zyga@x240 ~/D/libzt (feature/defer)> make check
SHELLCHECK configure
MAN man/ZT_CMP_BOOL.3
MAN man/ZT_CMP_INT.3
MAN man/ZT_CMP_PTR.3
MAN man/ZT_CMP_RUNE.3
MAN man/ZT_CMP_UINT.3
MAN man/ZT_CURRENT_LOCATION.3
MAN man/ZT_FALSE.3
MAN man/ZT_NOT_NULL.3
MAN man/ZT_NULL.3
MAN man/ZT_TRUE.3
MAN man/libzt-test.1
MAN man/libzt.3
MAN man/zt_check.3
MAN man/zt_claim.3
MAN man/zt_closure.3
mdoc warning: A .Bd directive has no matching .Ed (#20)
MAN man/zt_closure_func0.3
MAN man/zt_closure_func1.3
MAN man/zt_defer.3
Usage: .Fn function_name [function_arg] ... (#16)
MAN man/zt_location.3
MAN man/zt_location_at.3
MAN man/zt_main.3
MAN man/zt_pack_boolean.3
MAN man/zt_pack_closure0.3
mdoc warning: A .Bd directive has no matching .Ed (#20)
MAN man/zt_pack_closure1.3
mdoc warning: A .Bd directive has no matching .Ed (#21)
MAN man/zt_pack_integer.3
MAN man/zt_pack_nothing.3
MAN man/zt_pack_pointer.3
MAN man/zt_pack_rune.3
MAN man/zt_pack_string.3
MAN man/zt_pack_unsigned.3
MAN man/zt_test.3
MAN man/zt_test_case_func.3
MAN man/zt_test_suite_func.3
MAN man/zt_value.3
MAN man/zt_visit_test_case.3
MAN man/zt_visitor.3
PLOG-CONVERTER zt.c.PVS-Studio.log zt-test.c.PVS-Studio.log static-check-pvs
EXEC libzt-test
libzt self-test successful

I will let you decide which output is more readable. Did you spot the mdoc warning lines on your first read? If you build system supports that, consider using silend rules and fix those warnings you now see.