Cargo keeps entire rustc/rustdoc stdout in memory

[Aaron1011]

Problem

When cargo invokes rustc or rustdoc (via cargo doc or cargo build, the child process's entire stdout is kept in memory. This can lead to the system's memory being completely exhausted if rustc or rustdoc produce a lot of output (e.g. when RUST_LOG is set).

Steps

1. Create a file called yes.sh containing the string yes (If the yes program is unavailable, replace it with a script that endlessly writes to stdout)
2. Run chmod +x ./yes.sh
3. Run RUSTC=./yes.sh cargo build in any crate directory.
4. Observe that cargo's memory usage quickly rises to consume all available memory.

Possible Solution(s)

cargo should clear each line of a child command's stdout from memory once it has been printed, since it won't be needed again.

Notes

Output of cargo version: cargo 1.29.0 (524a578d7 2018-08-05)
Tested on Arch Linux - this should be reproducible on any Linux-based system.

[ishitatsuyuki]

I disagree. We don't have buffering yet, and yes if buffering is implemented your solution address a part of the problem.

The problem is simply that we don't have backpressure for consuming logs as we use an unbounded channel. yes is simply producing output too fast than we can forward. As a result, this is unlikely to actually blow things up in reality.

Fix: make this bounded.

cargo/src/cargo/core/compiler/job_queue.rs

Line 135 in 2d0863f

let (tx, rx) = channel();

[Aaron1011]

@ishitatsuyuki: This did come up for real - setting RUST_LOG=debug when compiling a large crate causes it for me. The yes example was just a convenient way to reliably reproduce it.

[ehuss]

I think there are multiple issues here.

Simple commands like rustc -Vv use command.output() which buffers the entire output. exec_with_output is used in a few places to call rustc to gather information. The yes example hits these situations, so it may be a little artificial since these usually should emit only a small amount of output even with debugging.

During the normal compile execution, even though the output is streamed to the terminal, internally it buffers the entire result here. This is used in a few cases (like capturing build script output), but for the case of running rustc I don't believe it is necessary.

[alexcrichton]

I think the correct fix here is to have Cargo discard rustc's output when it otherwise doesn't need to capture it, and I think that should be relatively easy to do?

[Aaron1011]

This issue is back - I haven't managed to find a minimized reproduction yet, but building the compiler with RUSTC_LOG=rustc::traits=debug ./x.py build causes cargo to consume multiple gigabytes of memory.

[Aaron1011]

Can this issue be re-opened? I've run into this again today, and it's making debugging quite difficult.

[Mark-Simulacrum]

This must have slipped into beta. Reopening; we might want to try and backport my PR to beta I guess?

[ehuss]

Considering the release is in two weeks, can it wait? @Aaron1011, would it be possible to confirm that it is fixed? Set cargo in config.toml to a nightly version of cargo and see if you can reproduce the problem?

[Aaron1011]

@ehuss: I can't seem to get rustup to use the newer version: cargo +stage1 --version prints cargo 1.42.0-nightly (ad3dbe10e 2020-01-13)

[ehuss]

I'm not sure what you mean by "use the newer version" (that seems like a very recent nightly).

When you use rustup links (like +stage1), rustup has a built-in fallback to use the nightly toolchain when cargo is not found. By default, ./x.py does not build cargo, nor does it place it into the stage1 directory.

x.py by default uses the cargo version from the last beta. If you modify cargo in config.toml to point to a recent cargo (like /Users/eric/.rustup/toolchains/nightly-x86_64-apple-darwin/bin/cargo in my case), then x.py will use that cargo to build rustc.

[Aaron1011]

@ehuss: I was able to reproduce the issue with that nightly (1.42.0-nightly (ad3dbe10e 2020-01-13)) - should I test a newer one as well?

[ehuss]

There are two issues here, neither of which are particularly easy to fix.

1. Fresh jobs do not spawn a new thread (src). This causes the main thread to block, so it fails to process Messages, so Read cached output line-by-line #7737 didn't actually fix the issue.

2. As mentioned above, the message queue does not have any sort of back pressure, so the messages bunch up inside the queue when it can't print them fast enough.

[LoganDark]

This is cargo build.

While writing that sentence, it grew even more.

[ehuss]

@LoganDark an you share more details about what you are doing? It might help to file a new issue. There are some known situations where Cargo buffers the output from rustc (such as the initial rustc --version discovery), but otherwise it shouldn't be buffering or consuming excessive memory. It also would help to share which version of cargo you are using.