SUMMARY Heaptrack hangs indefinitely tracing the rust compiler STEPS TO REPRODUCE 1. rustup install 1.49.0 (or any other rust compiler, I tried as far back as 1.45.2) 2. heaptrack $(rustup which rustc) --version OBSERVED RESULT The rustc process exits, but heaptrack hangs indefinitely: ``` > heaptrack $(rustup which rustc) --version heaptrack output will be written to "/home/joshua/test-rustdoc/heaptrack.rustc.13227.gz" starting application, this might take some time... rustc 1.51.0-nightly (a62a76047 2021-01-13) ``` sh -x shows that it's waiting for heaptrack_analyze to exit: ``` > sh -x $(which heaptrack) $(rustup which rustc) --version + INTERPRETER=/usr/local/bin/../lib/heaptrack/libexec/heaptrack_interpret + pipe=/tmp/heaptrack_fifo13302 + COMPRESSOR=gzip -c + output=/home/joshua/test-rustdoc/heaptrack.rustc.13302.gz + debuggee=13314 + wait 13314 ``` EXPECTED RESULT Heaptrack exits when the process being debugged exits. SOFTWARE/OS VERSIONS Linux: Debian 10 ADDITIONAL INFORMATION heaptrack 1.2.80 `heaptrack ls` or other small programs works fine.
I can reproduce the same issue with: - heaptrack 1.1.80 running on Ubuntu 20.04 (in WSL2) - with rustc 1.51 nightly
This used to work in Rust 1.32.0 but broke in Rust 1.33.0. ``` > heaptrack $(rustup which rustc --toolchain 1.32.0) --version heaptrack output will be written to "/home/joshua/test-rustdoc/heaptrack.rustc.27573.gz" starting application, this might take some time... rustc 1.32.0 (9fda7c223 2019-01-16) ../src/interpret/heaptrack_interpret.cpp:348 ERROR:Failed to create backtrace state for module /lib/x86_64-linux-gnu/libdl.so.2: ranges offset out of range / Success (error code 0) heaptrack stats: allocations: 346 leaked allocations: 7 temporary allocations: 26 Heaptrack finished! Now run the following to investigate the data: heaptrack --analyze "/home/joshua/test-rustdoc/heaptrack.rustc.27573.gz" > heaptrack $(rustup which rustc --toolchain 1.33.0) --version heaptrack output will be written to "/home/joshua/test-rustdoc/heaptrack.rustc.27536.gz" starting application, this might take some time... rustc 1.33.0 (2aa4c46cf 2019-02-28) ^C ```
`heaptrack rustdoc --version` works correctly.
thanks for the report, I can't give you any ETA on when I have the time to look into this as I'm pretty swamped in the current situation. could you maybe try to inspect it yourself? Basically you'd have to build heaptrack from source yourself and then enable logging - that would be my first step too. Maybe we can see something fishy by looking at the log then. basically all you need to do is checkout current master, create a build dir, run `cmake -DCMAKE_BUILD_TYPE=RelWithDebInfo path/to/sources && cmake --build .`, then see if you can run it: ``` ./bin/heaptrack ./tests/manual/test_c heaptrack output will be written to "/home/milian/projects/build/heaptrack/heaptrack.test_c.25458.zst" starting application, this might take some time... malloc: 0x5614afb04160 heaptrack stats: allocations: 3 leaked allocations: 0 temporary allocations: 0 Heaptrack finished! Now run the following to investigate the data: heaptrack --analyze "/home/milian/projects/build/heaptrack/heaptrack.test_c.25458.zst" ``` then enable logging by editing path/to/heaptrack/src/track/libheaptrack.cpp and change constexpr const DebugVerbosity s_debugVerbosity = NoDebugOutput; to constexpr const DebugVerbosity s_debugVerbosity = VeryVerboseOutput; recompile, then run on rustc and pipe the full output into a log file. then attach the compressed log file here please thanks
Millian, thanks for getting back. Unfortunately, heaptrack has absolutely no output on the Rust compiler. I confirmed it has logging for other programs: ``` > bin/heaptrack lsheaptrack output will be written to "/home/joshua/heaptrack/build/heaptrack.ls.4864.gz" starting application, this might take some time... heaptrack debug(3) [4877:4877]@0 heaptrack_malloc(0x7f753d13a3a8, 32) heaptrack debug(3) [4877:4877]@0 acquiring lock ... ``` but not on rustc: ``` > bin/heaptrack /home/joshua/.local/lib/rustup/toolchains/nightly-x86_64-unknown-linux-gnu/bin/rustc heaptrack output will be written to "/home/joshua/heaptrack/build/heaptrack.rustc.4885.gz" starting application, this might take some time... Usage: rustc [OPTIONS] INPUT ... rest of the help options ... ^C ```
Simply calling heaptrack to track rustc seems to work: ``` bin/heaptrack rustc --version heaptrack output will be written to "/home/dani/heaptrack/build/heaptrack.rustc.9925.gz" starting application, this might take some time... heaptrack debug(3) [9938:9938]@0 heaptrack_malloc(0x7fd450230320, 32) heaptrack debug(3) [9938:9938]@0 acquiring lock heaptrack debug(3) [9938:9938]@0 lock acquired heaptrack debug(3) [9938:9938]@0 releasing lock heaptrack debug(1) [9938:9938]@0 heaptrack_init(/tmp/heaptrack_fifo9925) heaptrack debug(3) [9938:9938]@0 acquiring lock heaptrack debug(3) [9938:9938]@0 lock acquired heaptrack debug(1) [9938:9938]@0 initializing: /tmp/heaptrack_fifo9925 heaptrack debug(1) [9938:9938]@0 calling initBeforeCallback heaptrack debug(1) [9938:9938]@0 done calling initBeforeCallback heaptrack debug(1) [9938:9938]@0 doing once-only initialization heaptrack debug(2) [9938:9938]@0 will write to /tmp/heaptrack_fifo9925/0x3 heaptrack debug(1) [9938:9938]@0 constructing LockedData heaptrack debug(1) [9938:9939]@0 timer thread started heaptrack debug(1) [9938:9938]@0 initialization done heaptrack debug(3) [9938:9938]@0 releasing lock heaptrack debug(3) [9938:9938]@0 heaptrack_malloc(0x55a52e3ec4d0, 72704) heaptrack debug(3) [9938:9938]@0 acquiring lock heaptrack debug(3) [9938:9938]@0 lock acquired heaptrack debug(1) [9938:9938]@0 updateModuleCache() heaptrack debug(2) [9938:9938]@0 dlopen_notify_callback: x 55a52d40f000 ``` But this hangs forever: bin/heaptrack $(rustup which rustc) --version heaptrack output will be written to "/home/dani/heaptrack/build/heaptrack.rustc.10419.gz" starting application, this might take some time... rustc 1.51.0-nightly (44e3daf5e 2020-12-31)
Created attachment 135038 [details] attachment-21296-0.html Right - `heaptrack` is just tracking the rustup shim for rustc, which is not very helpful. It doesn't include any info about the compiler itself. On Thu, Jan 21, 2021 at 2:09 PM Dániel Buga <bugzilla_noreply@kde.org> wrote: > https://bugs.kde.org/show_bug.cgi?id=431746 > > --- Comment #6 from Dániel Buga <bugadani@gmail.com> --- > Simply calling heaptrack to track rustc seems to work: > > ``` > bin/heaptrack rustc --version > heaptrack output will be written to > "/home/dani/heaptrack/build/heaptrack.rustc.9925.gz" > starting application, this might take some time... > heaptrack debug(3) [9938:9938]@0 heaptrack_malloc(0x7fd450230320, 32) > heaptrack debug(3) [9938:9938]@0 acquiring lock > heaptrack debug(3) [9938:9938]@0 lock acquired > heaptrack debug(3) [9938:9938]@0 releasing lock > heaptrack debug(1) [9938:9938]@0 heaptrack_init(/tmp/heaptrack_fifo9925) > heaptrack debug(3) [9938:9938]@0 acquiring lock > heaptrack debug(3) [9938:9938]@0 lock acquired > heaptrack debug(1) [9938:9938]@0 initializing: /tmp/heaptrack_fifo9925 > heaptrack debug(1) [9938:9938]@0 calling initBeforeCallback > heaptrack debug(1) [9938:9938]@0 done calling initBeforeCallback > heaptrack debug(1) [9938:9938]@0 doing once-only initialization > heaptrack debug(2) [9938:9938]@0 will write to /tmp/heaptrack_fifo9925/0x3 > > heaptrack debug(1) [9938:9938]@0 constructing LockedData > heaptrack debug(1) [9938:9939]@0 timer thread started > heaptrack debug(1) [9938:9938]@0 initialization done > heaptrack debug(3) [9938:9938]@0 releasing lock > heaptrack debug(3) [9938:9938]@0 heaptrack_malloc(0x55a52e3ec4d0, 72704) > heaptrack debug(3) [9938:9938]@0 acquiring lock > heaptrack debug(3) [9938:9938]@0 lock acquired > heaptrack debug(1) [9938:9938]@0 updateModuleCache() > heaptrack debug(2) [9938:9938]@0 dlopen_notify_callback: x 55a52d40f000 > ``` > > But this hangs forever: > > bin/heaptrack $(rustup which rustc) --version > heaptrack output will be written to > "/home/dani/heaptrack/build/heaptrack.rustc.10419.gz" > starting application, this might take some time... > rustc 1.51.0-nightly (44e3daf5e 2020-12-31) > > -- > You are receiving this mail because: > You reported the bug.
I see, interesting. is the shim doing anything special? maybe it's handling of execve/fork is messing up something in heaptrack. anyhow, a proper solution is probably going to mean adding the capability to track child processes somehow. that's a longstanding whish request which I sadly never got around to implement.
(In reply to Milian Wolff from comment #8) > I see, interesting. is the shim doing anything special? maybe it's handling > of execve/fork is messing up something in heaptrack. anyhow, a proper > solution is probably going to mean adding the capability to track child > processes somehow. that's a longstanding whish request which I sadly never > got around to implement. The hangs are not when running on the shim. If I bypass the shim and run on the compiler directly (that's what `rustup which rustc` does), that's when it hangs.
Hi Milian, is there anything more I can do to help debug this? Happy to collect more info if you think it would be useful.
Hey, sorry for the delay. I guess you'd have to figure out what the actual difference is between the two ways to run rustc. What does this expand to: rustup which rustc which rustc What does `file` say about the two paths? Is one a shell script or something else maybe? Can you attach strace logs for running both versions, i.e. something like `strace -e file -e process -f`
Milian, The default rustc in path is just a shim, it's not important. Rustup uses it to switch between the stable and nightly compilers. Heaptrack can run on it fine, because it's only tracking the shim and not the compiler itself (the shim spawns the compiler as a new process). > Can you attach strace logs for running both versions, i.e. something like `strace -e file -e process -f` Here's an strace for the actual compiler: $ strace -e file -e process -f /home/joshua/.local/lib/rustup/toolchains/nightly-x86_64-unknown-linux-gnu/bin/rustc --version execve("/home/joshua/.local/lib/rustup/toolchains/nightly-x86_64-unknown-linux-gnu/bin/rustc", ["/home/joshua/.local/lib/rustup/t"..., "--version"], 0x7ffec9ecad90 /* 34 vars */) = 0 arch_prctl(ARCH_SET_FS, 0x7f5f5e98a4c0) = 0 rustc 1.52.0-nightly (0148b971c 2021-02-18) exit_group(0) = ? +++ exited with 0 +++ I'll attach a full strace with all syscalls shown in just a second.
Created attachment 135919 [details] strace of `rustc --version` (without going through the shim)
ok, the problem is that rustc links against jemalloc statically: nm -aD $(rustup which rustc) | grep malloc 0000000000006ea0 T malloc 0000000000253020 D __malloc_hook 000000000000caa0 T malloc_usable_size That means LD_PRELOAD won't work for this use case. We'd have to change our injection code somehow, to allow using that instead. Though even then I'm unsure if it's possible to apply our logic there - static linking simply defeats the "attack surface" that heaptrack relies on to intercept the calls to malloc and friends...