Inconsistent build timeouts

Over the past month (at least, maybe two), we have been having curious build timeouts, where out of two builds with the same compiler and source revision, one will timeout and the other will succeed. Is there something going on in the backend? For example, https://builds.tuxbuild.com/20c9r8xZ2zlODkKcO92WuHmvWLg/ timed out but https://builds.tuxbuild.com/20cn4xZ4nDlIF8Q4pSsTUGwHdIJ/ succeeded; given there was only four hours between them (same source revision) and clang was last built on October 27th (from a revision on June 28th), I would expect the results to be the exact same. As a side note, it would be nice to have metadata.json for timed out builds as well so we can see the exact compiler version string.

cc @nickdesaulniers

I have compared the 2 builds. Looks like the timeout happened after 3 hrs boundary but the build was nearing the completion stage i.e tarring all the modules. It could just be that the build ran on a slower machine. We will look into recent timeouts to see if this is the pattern.

Another potential timeout for the same reason: https://builds.tuxbuild.com/20ezAykjxYyetyafjRELh2iXTbQ/

@nathanchance We have agreed to increase the build timeout from 3hrs to 4hrs since these builds are taking more than 3 hrs to finish. We also plan to add timestamp in tuxmake logs to reflect where the build actually stopped executing.

assigned to @stylesen

The builds that timeout have run on all types of machines from our pool so it is not a slow machine causing the timeout.

Also there is nothing else running in the background which could affect the build time.

A few more failed builds: https://github.com/ClangBuiltLinux/continuous-integration2/actions/runs/1479063191

For example, testing https://builds.tuxbuild.com/217Eds5iXgXYGMQXg59SNyougb5/ locally on my 64 thread machine:

$ tuxmake -a arm64 -k allmodconfig -K CONFIG_WERROR=n -r podman -t clang-12 CROSS_COMPILE_COMPAT=arm-linux-gnueabihf- LLVM=1 LLVM_IAS=1
...
I: config: PASS in 0:00:07.691308
I: default: PASS in 0:13:43.800073
I: kernel: PASS in 0:00:05.664149
I: xipkernel: SKIP in 0:00:00.293470
I: modules: PASS in 0:07:28.587888
I: dtbs: PASS in 0:00:08.067669
I: dtbs-legacy: SKIP in 0:00:00.390786
I: debugkernel: PASS in 0:00:11.339249
I: headers: PASS in 0:00:02.748245
...

If I am reading that right, that means the kernel build took 13m 43s seconds and installing then archiving the modules took 7m 28s (so 33% of the total tuxmake time was spent archiving the modules). That seems excessive to me, perhaps tuxmake#161 (closed) is relevant here? When I benchmarked the compression algorithms a year and a half ago, xz was significantly worse than all other algorithms when it comes to {,de}compression speed even though it offered the best compression ratio. Perhaps switching to an algorithm like zstd might be worth exploring, as it offers better {,de}compression speed than xz with a comparable compression ratio, meaning more builds within a set timespan.

as I commented in tuxmake#161 (closed), we could play around with the different xz compression levels.

e.g. on some simple local test with an arm64 modules tarball:

default compression level:

$ time xz --keep modules.tar 

real	0m16,839s
user	0m16,781s
sys	0m0,048s
tmp$ ll modules.tar*
-rw-r--r-- 1 terceiro terceiro 7,5M nov 19 13:55 modules.tar.xz
-rw-r--r-- 1 terceiro terceiro  43M nov 19 13:55 modules.tar

Lowest compression level (faster):

$ time xz --keep -0 modules.tar 

real	0m1,855s
user	0m1,827s
sys	0m0,028s
tmp$ ll modules.tar*
-rw-r--r-- 1 terceiro terceiro 8,8M nov 19 13:55 modules.tar.xz
-rw-r--r-- 1 terceiro terceiro  43M nov 19 13:55 modules.tar

In this case -0 is 1 order of magnitude faster than the default, and the resulting compression is not bad: 20% or the original size, vs 17% with the default compression.

For reference, the build that produced that modules tarball took 21s in the modules target.

For comparison:

gzip:

tmp$ time gzip --keep modules.tar

real	0m1,726s
user	0m1,706s
sys	0m0,020s
tmp$ ll modules.tar.gz 
-rw-r--r-- 1 terceiro terceiro 12M nov 19 13:55 modules.tar.gz

i.e. xz -0 is as fast as the default gzip compression level with better compression ratio.

tmp$ time zstd --keep modules.tar
modules.tar          : 26.25%   (44134400 => 11583312 bytes, modules.tar.zst)  

real	0m0,245s
user	0m0,237s
sys	0m0,021s
tmp$ ll modules.tar.zst 
-rw-r--r-- 1 terceiro terceiro 12M nov 19 13:55 modules.tar.zst

zstd has the worse compression ration by default, but is a lot faster.

zstd is usually a really good tradeoff. Is that difficult to change in tuxmake?

well just making a search and replace would be easy, but I would not want to be locked in to a new compressor and rather have a mechanism to choose. Also switching compression methods might break automation that people might have in place (looking for *.xz).

Something that would help a lot without any change, right now, would be setting XZ_OPT=-0 in the environment for the tuxmake build in the TuxBuild backend.

Based on the discussions on this issue, we have implemented the following which will help us to improve / neglect seeing long running builds:

• Build timeout increased to 240 minutes
• build_debug.log published with time stamped lines to see how long each step took (build.log is still available as before)
• tuxbuild uses xz level 0 compression to compress the modules instead of the default level 6 which (may) help in reducing the overall time taken for large builds
  • compression time should drop by 1 order of magnitude

This is one of the longest build https://builds.tuxbuild.com/21OB64WZb0jESRxrm2s67TRLirm/ which took about 2 hrs 40 minutes to finish today. Looking at the logs the module tarball creation with latest optimization took 10 minutes to finish. It looks like tarball creation also contributed the timeout.

I have resubmitted the same build again to see if build times vary compared to the above build: https://builds.tuxbuild.com/21PjCX8jLMDjh28D2yIs0fCTG0d/

It appears the changes implemented have generally helped, as I see a lot fewer timeouts (most of our recent failures have been due to GitHub Actions). However, this build is rather peculiar because it says that it timed out on the build step but it produced an Image.gz, which appears to boot and work fine in QEMU. Did something go wrong on the backend? Additionally, the result that we pulled down says the result is "unknown" and that it is running. Was there a race with the tuxsuite client finishing the build and our CI trying to get the result?

@nathanchance this build timed out while building modules and hence you have the Image.gz but no modules. We will increase the timeout marginally so that the builds don't timeout.

@nathanchance would like to get your answers on the following:

1. Is there a possibility of toolchain getting into a loop causing the build to get hung? Have you observed such issues in the past?
2. How can we check if clang toolchain process is functioning while doing the build?

We have tried debugging on a live machine that is running build taking more than 3 hours and saw that builds cached hangs sometime and un-cached builds such as the ones using clang nightly toolchain which do not use sccache also hangs, in different machine configurations. Hence the above questions which will be helpful for us to debug on a live machine when the build happens and find out the root cause.

@stylesen I was just getting ready to make a comment around sccache because I saw this build timed out, even though metadata.json showed that the build was mostly cached (21,520 hits, 12 misses). If uncached builds hang though, it might not be that.

1. Yes, it is possible for the compiler to enter an infinite loop while compiling, I have observed it before: https://github.com/ClangBuiltLinux/linux/issues/1261, https://github.com/ClangBuiltLinux/linux/issues/1431. It is less likely to happen on released versions of clang, since those will have been fairly well battle tested by the time they are released but I suppose it is still possible.

2. If you are debugging this while the build is happening in real time, I usually use htop to see what file clang is building when it hangs so that I can try to build the single file (make <path>.o) and see if it hangs that way. I am not really sure of a way to do this programmatically... it is possible you could use the etime field from ps to get the elapsed time of all clang invocations and if one is longer than say, a minute, you kill the build and report the unit that hung?

If clang-nightly builds are hanging without sccache and those hangs are reproducible on many different machines, let us know because that is likely an issue with upstream so we need reduce down the problematic file and get it reported so it can be fixed before the compiler releases. If the hangs are not reproducible from machine to machine, that is going to be harder to figure out what is going on (it is likely not the compiler at that point).

@nathanchance I have logged into a machine where the build was running for 3 hrs and check what is going on. I see that lld was running for more than 3 hrs. Here is the process:

$ ps -ef | grep -e "clang" -e "lld"
tuxbuild    4004    1443  0 01:19 ?        00:00:00 podman exec a6fd6d4f08ba7918c1a73b1bd37da7ac5c5262f30be8a49635c0ae361afceae9 /tuxmake/tuxmake-offline-build make --silent --keep-going --jobs=8 O=/home/tuxbuild/.cache/tuxmake/builds/current LLVM=1 LLVM_IAS=1 ARCH=arm64 CROSS_COMPILE=aarch64-linux-gnu- CROSS_COMPILE_COMPAT=arm-linux-gnueabihf- HOSTCC=sccache clang CC=sccache clang
tuxbuild    4041    4004  0 01:19 ?        00:00:06 podman exec a6fd6d4f08ba7918c1a73b1bd37da7ac5c5262f30be8a49635c0ae361afceae9 /tuxmake/tuxmake-offline-build make --silent --keep-going --jobs=8 O=/home/tuxbuild/.cache/tuxmake/builds/current LLVM=1 LLVM_IAS=1 ARCH=arm64 CROSS_COMPILE=aarch64-linux-gnu- CROSS_COMPILE_COMPAT=arm-linux-gnueabihf- HOSTCC=sccache clang CC=sccache clang
tuxbuild    4090    4086  0 01:19 ?        00:00:00 /bin/sh /tuxmake/tuxmake-offline-build make --silent --keep-going --jobs=8 O=/home/tuxbuild/.cache/tuxmake/builds/current LLVM=1 LLVM_IAS=1 ARCH=arm64 CROSS_COMPILE=aarch64-linux-gnu- CROSS_COMPILE_COMPAT=arm-linux-gnueabihf- HOSTCC=sccache clang CC=sccache clang
tuxbuild    4101    4090  0 01:19 ?        00:00:00 make --silent --keep-going --jobs=8 O=/home/tuxbuild/.cache/tuxmake/builds/current LLVM=1 LLVM_IAS=1 ARCH=arm64 CROSS_COMPILE=aarch64-linux-gnu- CROSS_COMPILE_COMPAT=arm-linux-gnueabihf- HOSTCC=sccache clang CC=sccache clang
tuxbuild  129452  121317  0 01:25 ?        00:00:00 /bin/sh -c set -e;  exec >/dev/null; ld.lld -r -EL  -maarch64elf -z norelro --build-id=sha1  -T scripts/module.lds -o drivers/gpu/drm/exynos/exynosdrm.ko drivers/gpu/drm/exynos/exynosdrm.o drivers/gpu/drm/exynos/exynosdrm.mod.o;  true; printf '%s\n' 'cmd_drivers/gpu/drm/exynos/exynosdrm.ko := ld.lld -r -EL  -maarch64elf -z norelro --build-id=sha1  -T scripts/module.lds -o drivers/gpu/drm/exynos/exynosdrm.ko drivers/gpu/drm/exynos/exynosdrm.o drivers/gpu/drm/exynos/exynosdrm.mod.o;  true' > drivers/gpu/drm/exynos/.exynosdrm.ko.cmd
tuxbuild  129454  129452  0 01:25 ?        00:00:00 ld.lld -r -EL -maarch64elf -z norelro --build-id=sha1 -T scripts/module.lds -o drivers/gpu/drm/exynos/exynosdrm.ko drivers/gpu/drm/exynos/exynosdrm.o drivers/gpu/drm/exynos/exynosdrm.mod.o
ubuntu    137627  137510  0 04:54 pts/0    00:00:00 grep --color=auto -e clang -e lld

$ sudo ps -p 129452 -o etime
    ELAPSED
   03:27:01

The corresponding build for the above log is here.

I'll wait for the next build that will hit the timeout issue and check which process is running for so long.

@nathanchance I see similar wait for another build which is about to timeout:

$ ps -ef | grep -e "clang" -e "lld"
tuxbuild    3911    1447  0 12:34 ?        00:00:00 podman exec a1e0478c09b806912a9170c7a51d5e8775d76c6025e76417b9fb322ab39ea0f2 /tuxmake/tuxmake-offline-build make --silent --keep-going --jobs=8 O=/home/tuxbuild/.cache/tuxmake/builds/current LLVM=1 LLVM_IAS=1 ARCH=riscv CROSS_COMPILE=riscv64-linux-gnu- HOSTCC=sccache clang CC=sccache clang
tuxbuild    3947    3911  0 12:34 ?        00:00:10 podman exec a1e0478c09b806912a9170c7a51d5e8775d76c6025e76417b9fb322ab39ea0f2 /tuxmake/tuxmake-offline-build make --silent --keep-going --jobs=8 O=/home/tuxbuild/.cache/tuxmake/builds/current LLVM=1 LLVM_IAS=1 ARCH=riscv CROSS_COMPILE=riscv64-linux-gnu- HOSTCC=sccache clang CC=sccache clang
tuxbuild    3995    3991  0 12:34 ?        00:00:00 /bin/sh /tuxmake/tuxmake-offline-build make --silent --keep-going --jobs=8 O=/home/tuxbuild/.cache/tuxmake/builds/current LLVM=1 LLVM_IAS=1 ARCH=riscv CROSS_COMPILE=riscv64-linux-gnu- HOSTCC=sccache clang CC=sccache clang
tuxbuild    4006    3995  0 12:34 ?        00:00:00 make --silent --keep-going --jobs=8 O=/home/tuxbuild/.cache/tuxmake/builds/current LLVM=1 LLVM_IAS=1 ARCH=riscv CROSS_COMPILE=riscv64-linux-gnu- HOSTCC=sccache clang CC=sccache clang
tuxbuild  629097  507672  0 13:04 ?        00:00:00 /bin/sh -c set -e;  exec >/dev/null; ld.lld -r -melf64lriscv --build-id=sha1  -T scripts/module.lds -o drivers/video/fbdev/sstfb.ko drivers/video/fbdev/sstfb.o drivers/video/fbdev/sstfb.mod.o;  true; printf '%s\n' 'cmd_drivers/video/fbdev/sstfb.ko := ld.lld -r -melf64lriscv --build-id=sha1  -T scripts/module.lds -o drivers/video/fbdev/sstfb.ko drivers/video/fbdev/sstfb.o drivers/video/fbdev/sstfb.mod.o;  true' > drivers/video/fbdev/.sstfb.ko.cmd
tuxbuild  629099  629097  0 13:04 ?        00:00:00 ld.lld -r -melf64lriscv --build-id=sha1 -T scripts/module.lds -o drivers/video/fbdev/sstfb.ko drivers/video/fbdev/sstfb.o drivers/video/fbdev/sstfb.mod.o
ubuntu    646161  646057  0 16:07 pts/0    00:00:00 grep --color=auto -e clang -e lld

$ sudo ps -p 629099 -o etime
    ELAPSED
   03:04:42

@vishalbhoj would it be possible to get the .o files that it mentions in those commands? I cannot reproduce locally with tuxmake, it might be a caching problem?

@nathanchance I don't think it is a problem related to caching. We have seen this behaviour on clang-nightly based build as well which doesn't use cache. The issue is not reproducible as the same build when resubmitted finishes fine.

Here is one more such build from today: https://builds.tuxbuild.com/22ApBoqrHezQ8887AuUw4riUlyc/

I am attaching the *.o files and here is the command which is hung:

$ ps -ef | grep -e "clang" -e "lld"
tuxbuild    3377    1455  0 06:26 ?        00:00:00 podman exec 5047e53c51087d7dfbc325ac07cf551a064ce5f39516d8748ad7602bb046d013 /tuxmake/tuxmake-offline-build make --silent --keep-going --jobs=8 O=/home/tuxbuild/.cache/tuxmake/builds/current LLVM=1 LLVM_IAS=1 ARCH=arm64 CROSS_COMPILE=aarch64-linux-gnu- CROSS_COMPILE_COMPAT=arm-linux-gnueabihf- HOSTCC=sccache clang CC=sccache clang
tuxbuild    3414    3377  0 06:26 ?        00:00:08 podman exec 5047e53c51087d7dfbc325ac07cf551a064ce5f39516d8748ad7602bb046d013 /tuxmake/tuxmake-offline-build make --silent --keep-going --jobs=8 O=/home/tuxbuild/.cache/tuxmake/builds/current LLVM=1 LLVM_IAS=1 ARCH=arm64 CROSS_COMPILE=aarch64-linux-gnu- CROSS_COMPILE_COMPAT=arm-linux-gnueabihf- HOSTCC=sccache clang CC=sccache clang
tuxbuild    3463    3459  0 06:26 ?        00:00:00 /bin/sh /tuxmake/tuxmake-offline-build make --silent --keep-going --jobs=8 O=/home/tuxbuild/.cache/tuxmake/builds/current LLVM=1 LLVM_IAS=1 ARCH=arm64 CROSS_COMPILE=aarch64-linux-gnu- CROSS_COMPILE_COMPAT=arm-linux-gnueabihf- HOSTCC=sccache clang CC=sccache clang
tuxbuild    3472    3463  0 06:26 ?        00:00:00 make --silent --keep-going --jobs=8 O=/home/tuxbuild/.cache/tuxmake/builds/current LLVM=1 LLVM_IAS=1 ARCH=arm64 CROSS_COMPILE=aarch64-linux-gnu- CROSS_COMPILE_COMPAT=arm-linux-gnueabihf- HOSTCC=sccache clang CC=sccache clang
tuxbuild  474193  378887  0 06:52 ?        00:00:00 /bin/sh -c set -e;  exec >/dev/null; ld.lld -r -EL  -maarch64elf -z norelro --build-id=sha1  -T scripts/module.lds -o net/bridge/netfilter/ebt_ip6.ko net/bridge/netfilter/ebt_ip6.o net/bridge/netfilter/ebt_ip6.mod.o;  true; printf '%s\n' 'cmd_net/bridge/netfilter/ebt_ip6.ko := ld.lld -r -EL  -maarch64elf -z norelro --build-id=sha1  -T scripts/module.lds -o net/bridge/netfilter/ebt_ip6.ko net/bridge/netfilter/ebt_ip6.o net/bridge/netfilter/ebt_ip6.mod.o;  true' > net/bridge/netfilter/.ebt_ip6.ko.cmd
tuxbuild  474194  474193  0 06:52 ?        00:00:00 ld.lld -r -EL -maarch64elf -z norelro --build-id=sha1 -T scripts/module.lds -o net/bridge/netfilter/ebt_ip6.ko net/bridge/netfilter/ebt_ip6.o net/bridge/netfilter/ebt_ip6.mod.o
ubuntu    484013  483997  0 09:59 pts/0    00:00:00 grep --color=auto -e clang -e lld
$ sudo ps -p 474194 -o etime
    ELAPSED
   03:06:43

I ran podman container and tried running the same command and it passed:

$ podman run -it -v /home/tuxbuild/:/tuxbuild  tuxmake/arm64_clang-13:latest
root@907e8509c68f:/tuxbuild#  ld.lld -r -EL -maarch64elf -z norelro --build-id=sha1 -T module.lds -o a.ko ebt_ip6.o
root@907e8509c68f:/tuxbuild#  ls -la a.ko
-rw-r--r--  1 root root 467096 Dec 12 10:05 a.ko

module.lds

ebt_ip6.o

ebt_ip6.mod.o

Could you run strace -p <pid> on the hanging process so we can see what this process is doing?

If it's waiting for a fd, look at ls -l /proc/<pid>/fd.

It is hung waiting at futex_wait_private. I'll get the details the next time I get hold of timing out build.

@nathanchance I induced a sigtrap to the lld process to get a coredump to find out where it was waiting. This caused the build to be marked as failed: https://builds.tuxbuild.com/22Fr2U2QXcqVaiiBfIvR8i0J4kU/

Here is the traceback from the logs:

Stack dump:
0.	Program arguments: ld.lld -r -melf64lriscv --build-id=sha1 -T scripts/module.lds -o drivers/leds/trigger/ledtrig-netdev.ko drivers/leds/trigger/ledtrig-netdev.o drivers/leds/trigger/ledtrig-netdev.mod.o
 #0 0x00007f0bf91069f1 llvm::sys::PrintStackTrace(llvm::raw_ostream&, int) (/usr/lib/x86_64-linux-gnu/libLLVM-14.so.1+0xed59f1)
 #1 0x00007f0bf91047fe llvm::sys::RunSignalHandlers() (/usr/lib/x86_64-linux-gnu/libLLVM-14.so.1+0xed37fe)
 #2 0x00007f0bf9106f2b (/usr/lib/x86_64-linux-gnu/libLLVM-14.so.1+0xed5f2b)
 #3 0x00007f0bfeaf0140 __restore_rt (/lib/x86_64-linux-gnu/libpthread.so.0+0x14140)
 #4 0x00007f0bfeaeb7b2 pthread_cond_wait@@GLIBC_2.3.2 (/lib/x86_64-linux-gnu/libpthread.so.0+0xf7b2)
 #5 0x00007f0bf812d90c std::condition_variable::wait(std::unique_lock<std::mutex>&) (/usr/lib/x86_64-linux-gnu/libstdc++.so.6+0xc990c)
 #6 0x00007f0bf907e76b llvm::parallel::detail::TaskGroup::~TaskGroup() (/usr/lib/x86_64-linux-gnu/libLLVM-14.so.1+0xe4d76b)
 #7 0x000000000063d38e void llvm::parallel::detail::parallel_for_each_n<unsigned long, void lld::elf::OutputSection::writeTo<llvm::object::ELFType<(llvm::support::endianness)1, true> >(unsigned char*)::'lambda'(unsigned long)>(unsigned long, unsigned long, void lld::elf::OutputSection::writeTo<llvm::object::ELFType<(llvm::support::endianness)1, true> >(unsigned char*)::'lambda'(unsigned long)) (/usr/lib/llvm-14/bin/lld+0x63d38e)
 #8 0x000000000063501a void lld::elf::OutputSection::writeTo<llvm::object::ELFType<(llvm::support::endianness)1, true> >(unsigned char*) (/usr/lib/llvm-14/bin/lld+0x63501a)
 #9 0x00000000006f3cee void lld::elf::writeResult<llvm::object::ELFType<(llvm::support::endianness)1, true> >() (/usr/lib/llvm-14/bin/lld+0x6f3cee)
#10 0x000000000058e6c5 void lld::elf::LinkerDriver::link<llvm::object::ELFType<(llvm::support::endianness)1, true> >(llvm::opt::InputArgList&) (/usr/lib/llvm-14/bin/lld+0x58e6c5)
#11 0x000000000057fb5d lld::elf::LinkerDriver::linkerMain(llvm::ArrayRef<char const*>) (/usr/lib/llvm-14/bin/lld+0x57fb5d)
#12 0x000000000057d450 lld::elf::link(llvm::ArrayRef<char const*>, bool, llvm::raw_ostream&, llvm::raw_ostream&) (/usr/lib/llvm-14/bin/lld+0x57d450)
#13 0x00000000004ba3e1 (/usr/lib/llvm-14/bin/lld+0x4ba3e1)
#14 0x00000000004b9cdf main (/usr/lib/llvm-14/bin/lld+0x4b9cdf)
#15 0x00007f0bf7d67d0a __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x26d0a)
#16 0x00000000004b998a _start (/usr/lib/llvm-14/bin/lld+0x4b998a)
make[3]: *** [/builds/linux/scripts/Makefile.modfinal:60: drivers/leds/trigger/ledtrig-netdev.ko] Trace/breakpoint trap
make[3]: Target '__modfinal' not remade because of errors.
make[2]: *** [/builds/linux/scripts/Makefile.modpost:140: __modpost] Error 2
make[1]: *** [/builds/linux/Makefile:1761: modules] Error 2
make[1]: Target '__all' not remade because of errors.

I ran the same lld command on the machine for 1000 times and it worked fine using the same podman container. Do you any insights on this traceback ?

Hmmm, I don't, although it seems like there might be a race condition somewhere as the traceback says it is waiting for something? Perhaps @nickdesaulniers has an idea? The fact that it is not reproducible with the exact same build artifacts is really troubling, as that seems to point to some sort of non-determinism. You said these timeouts happen on various different machines, correct? Is there anything common between them, such as CPU, memory, or hard drive type?