Large memory usage and long time on compiling large number of println #86244

upsuper · 2021-06-12T11:11:40Z

Not sure whether it's a known bug.

I tried this code:

fn main() {
    println!("hello world!"); // repeat 16384 times
}

(To save you some time, you can download the file here directly rather than generating it yourself.)

I expected to see this happen: it should take reasonable amount of memory and reasonable time to compile.

Instead, this happened: on my machine, I saw it took up to 34GB memory and 2.5min of time just to compile this.

Meta

rustc --version --verbose:

rustc 1.52.1 (9bc8c42bb 2021-05-09)
binary: rustc
commit-hash: 9bc8c42bb2f19e745a63f3445f1ac248fb015e53
commit-date: 2021-05-09
host: x86_64-unknown-linux-gnu
release: 1.52.1
LLVM version: 12.0.0

The text was updated successfully, but these errors were encountered:

weiby3 · 2021-06-12T12:05:00Z

Another test, dbg! used more than 40G MEM.
test scripts:

echo 'fn main() {' > hw.rs
for i in {0..16384}
do
echo '    dbg!("Hello, world!");' >> hw.rs
done
echo '}' >> hw.rs
/usr/bin/time -f "%Uuser %Ssystem %Eelapsed %PCPU (%Xtext+%Ddata %Mmax)k\n%Iinputs+%Ooutputs (%Fmajor+%Rminor)pagefaults %Wswaps\nUsed %MKbytes Max Resident MEM" rustc hw.rs

log:

1044.19user 24.17system 18:08.63elapsed 98%CPU (0text+0data 39245668max)k
129736inputs+0outputs (2010major+17465633minor)pagefaults 0swaps
Used 39245668Kbytes Max Resident MEM

$ grep "Out of memory" /var/log/messages
Jun 12 19:58:32 centos kernel: Out of memory: Kill process 31123 (rustc) score 937 or sacrifice child

oxalica · 2021-06-12T14:07:56Z

I simplify the code to tons of &"foo", which is unexpectedly costly in both memory and time. (But not sure if it's the root cause of original code. The original code expands to &["hello"], and also have lifetime-generic function calls)

Generator script:

#!/usr/bin/env bash
exec >test.rs
echo 'fn main() {'
for i in $(seq 16384); do
    echo '&"foo";'
done
echo '}'

It costs 2.6GB memory and 50s to compile. While adding one more reference (&&"foo"; per line), it costs 4.3GB memory and 86s to compile.

For comparation, &&1i32; cost 300MB memory and 3.4s to compile.

inquisitivecrystal · 2021-06-12T20:46:15Z

@rustbot label I-compilemem I-compiletime T-compiler

nbdd0121 · 2021-06-12T20:59:17Z

Profiling shows that 97% of the time is spent in mir_borrowck.

nbdd0121 · 2021-06-12T22:27:00Z

Did some further analysis with perf, and get this call stack:

  Children      Self  Comma  Shared Object                        Symbol
-   97.02%     0.00%  rustc  librustc_driver-3894de7c87fd4580.so  [.] rustc_mir::borrow_check::do_mir_borrowck
   - 97.02% rustc_mir::borrow_check::do_mir_borrowck
      - 96.54% rustc_mir::borrow_check::nll::compute_regions
         - 95.54% rustc_mir::borrow_check::type_check::type_check
            - 95.38% <rustc_mir::borrow_check::type_check::TypeVerifier as rustc_middle::mir::visit::Visitor>::visit_body
               - 95.35% <rustc_mir::borrow_check::type_check::TypeVerifier as rustc_middle::mir::visit::Visitor>::visit_rvalue
                  - 95.26% <rustc_mir::borrow_check::type_check::TypeVerifier as rustc_middle::mir::visit::Visitor>::visit_constant
                       77.10% rustc_index::bit_set::HybridBitSet<T>::insert
                     + 6.18% <rustc_mir::borrow_check::type_check::TypeVerifier as rustc_middle::mir::visit::Visitor>::visit_body

Majority of the time is spent in <rustc_mir::borrow_check::type_check::TypeVerifier as rustc_middle::mir::visit::Visitor>::visit_constant, and a quite significant portion is in rustc_index::bit_set::HybridBitSet<T>::insert, presumably when updating liveness_constraints.

visit_constant is highly inlined, so I am not very confident about my analysis, but it seems to me that it's sanitize_promoted that uses majority of the time. ~~There is an for live_region in liveness_constraints.rows(), perhaps means that the algorithm is O(N^2) for the MCVE above (N constants * N regions)?~~ EDIT: looked again and it doesn't seem to be O(N^2) since swap_constraints means that each "promoted" has its own liveness_constraints.

I don't understand the code well enough to make any conclusions or make any changes, so perhaps someone more familiar with this code could give some hints.

memoryruins · 2021-06-16T01:39:51Z

#50994 uses 5,000 println!("hello world!");s to benchmark the compiler and compares debug/opt builds (though note the profiles are a few years old). Should the investigation here continue in that issue?

nbdd0121 · 2021-06-16T01:52:49Z

#50994 uses 5,000 println!("hello world!");s to benchmark the compiler and compares debug/opt builds (though note the profiles are a few years old). Should the investigation here continue in that issue?

The example by @oxalica shows that this issue has nothing to do with println! but with references.

#50994 is related to LLVM performance issue while this one is related to borrow checking. Note that when that issue is posted, Rust does not yet have stable NLL, so it's certainly a different issue from this one.

memoryruins · 2021-06-16T02:30:09Z

Both issues were opened with the premise of benchmarking the compiler with the same println! test case. The other issue is not only about LLVM. Its debug profiles suggest something similar to @oxalica 's findings and your perf profile. As noted, that's happening in a different part of rustc now, which is relevant information to post on the other issue, but it does not mean the two issues are different. Edited for clarity.

perf: Don't track specific live points for promoteds We don't query this information out of the promoted (it's basically a single "unit" regardless of the complexity within it) and this saves on re-initializing the SparseIntervalMatrix's backing IndexVec with mostly empty rows for all of the leading regions in the function. Typical promoteds will only contain a few regions that need up be uplifted, while the parent function can have thousands. For a simple function repeating println!("Hello world"); 50,000 times this reduces compile times from 90 to 15 seconds in debug mode. The previous implementations re-initialization led to an overall roughly n^2 runtime as each promoted initialized slots for ~n regions, now we scale closer to linearly (5000 hello worlds takes 1.1 seconds). cc rust-lang#50994, rust-lang#86244

…dtwco perf: Don't track specific live points for promoteds We don't query this information out of the promoted (it's basically a single "unit" regardless of the complexity within it) and this saves on re-initializing the SparseIntervalMatrix's backing IndexVec with mostly empty rows for all of the leading regions in the function. Typical promoteds will only contain a few regions that need up be uplifted, while the parent function can have thousands. For a simple function repeating println!("Hello world"); 50,000 times this reduces compile times from 90 to 15 seconds in debug mode. The previous implementations re-initialization led to an overall roughly n^2 runtime as each promoted initialized slots for ~n regions, now we scale closer to linearly (5000 hello worlds takes 1.1 seconds). cc rust-lang#50994, rust-lang#86244

perf: Don't track specific live points for promoteds We don't query this information out of the promoted (it's basically a single "unit" regardless of the complexity within it) and this saves on re-initializing the SparseIntervalMatrix's backing IndexVec with mostly empty rows for all of the leading regions in the function. Typical promoteds will only contain a few regions that need up be uplifted, while the parent function can have thousands. For a simple function repeating println!("Hello world"); 50,000 times this reduces compile times from 90 to 15 seconds in debug mode. The previous implementations re-initialization led to an overall roughly n^2 runtime as each promoted initialized slots for ~n regions, now we scale closer to linearly (5000 hello worlds takes 1.1 seconds). cc rust-lang/rust#50994, rust-lang/rust#86244

klensy · 2025-01-16T11:21:36Z

I simplify the code to tons of &"foo", which is unexpectedly costly in both memory and time. (But not sure if it's the root cause of original code. The original code expands to &["hello"], and also have lifetime-generic function calls)

Generator script:

#!/usr/bin/env bash
exec >test.rs
echo 'fn main() {'
for i in $(seq 16384); do
echo '&"foo";'
done
echo '}'
It costs 2.6GB memory and 50s to compile. While adding one more reference (&&"foo"; per line), it costs 4.3GB memory and 86s to compile.

For comparation, &&1i32; cost 300MB memory and 3.4s to compile.

As of today, rustc 1.86.0-nightly (8361aef 2025-01-14) compiles under 2s and < 250mb.

rustc -Copt-level=3 -Ztime-passes -Awarnings ./test.rs
time:   0.009; rss:   49MB ->   55MB (   +6MB)  parse_crate
time:   0.000; rss:   59MB ->   59MB (   +1MB)  crate_injection
time:   0.003; rss:   59MB ->   72MB (  +13MB)  expand_crate
time:   0.003; rss:   59MB ->   72MB (  +13MB)  macro_expand_crate
time:   0.000; rss:   72MB ->   72MB (   +0MB)  maybe_building_test_harness
time:   0.000; rss:   72MB ->   74MB (   +2MB)  finalize_macro_resolutions
time:   0.000; rss:   74MB ->   74MB (   +0MB)  late_resolve_crate
time:   0.000; rss:   74MB ->   74MB (   +0MB)  resolve_postprocess
time:   0.001; rss:   72MB ->   74MB (   +2MB)  resolve_crate
time:   0.006; rss:   74MB ->   81MB (   +7MB)  looking_for_entry_point
time:   0.000; rss:   82MB ->   82MB (   +0MB)  unused_lib_feature_checking
time:   0.007; rss:   74MB ->   82MB (   +7MB)  misc_checking_1
time:   0.001; rss:   82MB ->   84MB (   +2MB)  coherence_checking
time:   0.014; rss:   82MB ->   94MB (  +12MB)  type_check_crate
time:   0.976; rss:   94MB ->  205MB ( +111MB)  MIR_borrow_checking
time:   0.108; rss:  205MB ->  208MB (   +3MB)  MIR_effect_checking
time:   0.005; rss:  208MB ->  208MB (   +0MB)  lint_checking
time:   0.007; rss:  208MB ->  208MB (   +0MB)  misc_checking_3
time:   0.000; rss:  208MB ->  209MB (   +0MB)  monomorphization_collector_root_collections
time:   0.018; rss:  209MB ->  216MB (   +7MB)  monomorphization_collector_graph_walk
time:   0.000; rss:  216MB ->  216MB (   +0MB)  partition_and_assert_distinct_symbols
time:   0.001; rss:  218MB ->  223MB (   +5MB)  write_allocator_module
time:   0.001; rss:  227MB ->  241MB (  +14MB)  codegen_to_LLVM_IR
time:   0.022; rss:  208MB ->  242MB (  +33MB)  codegen_crate
time:   0.008; rss:  237MB ->  201MB (  -36MB)  LLVM_passes
time:   0.002; rss:  199MB ->  197MB (   -1MB)  finish_ongoing_codegen
time:   0.034; rss:  198MB ->  198MB (   +0MB)  run_linker
time:   0.035; rss:  197MB ->  198MB (   +1MB)  link_binary
time:   0.035; rss:  197MB ->  198MB (   +1MB)  link_crate
time:   0.036; rss:  197MB ->  198MB (   +1MB)  link
time:   1.198; rss:   32MB ->  101MB (  +70MB)  total

The same one but with println!("hello world!"); longer: 17s and ~ 750mb.

rustc -Copt-level=3 -Ztime-passes -Awarnings ./test2.rs
time:   0.013; rss:   49MB ->   59MB (  +10MB)  parse_crate
time:   0.000; rss:   63MB ->   63MB (   +1MB)  crate_injection
time:   0.246; rss:   63MB ->  138MB (  +75MB)  expand_crate
time:   0.246; rss:   63MB ->  138MB (  +75MB)  macro_expand_crate
time:   0.001; rss:  138MB ->  139MB (   +0MB)  AST_validation
time:   0.005; rss:  139MB ->  140MB (   +1MB)  finalize_macro_resolutions
time:   0.037; rss:  140MB ->  141MB (   +1MB)  late_resolve_crate
time:   0.002; rss:  141MB ->  141MB (   +0MB)  resolve_postprocess
time:   0.046; rss:  139MB ->  141MB (   +2MB)  resolve_crate
time:   0.003; rss:  153MB ->  152MB (   -1MB)  drop_ast
time:   0.060; rss:  141MB ->  153MB (  +12MB)  looking_for_entry_point
time:   0.078; rss:  141MB ->  153MB (  +12MB)  misc_checking_1
time:   0.005; rss:  153MB ->  155MB (   +2MB)  coherence_checking
time:   0.644; rss:  153MB ->  281MB ( +127MB)  type_check_crate
time:   1.426; rss:  281MB ->  444MB ( +164MB)  MIR_borrow_checking
time:   0.182; rss:  444MB ->  440MB (   -4MB)  MIR_effect_checking
time:   0.026; rss:  440MB ->  441MB (   +0MB)  module_lints
time:   0.026; rss:  440MB ->  441MB (   +0MB)  lint_checking
time:   0.029; rss:  441MB ->  441MB (   +0MB)  privacy_checking_modules
time:   0.059; rss:  440MB ->  441MB (   +0MB)  misc_checking_3
time:   0.000; rss:  441MB ->  441MB (   +0MB)  monomorphization_collector_root_collections
time:   1.775; rss:  441MB ->  699MB ( +258MB)  monomorphization_collector_graph_walk
time:   0.002; rss:  699MB ->  699MB (   +0MB)  partition_and_assert_distinct_symbols
time:   0.000; rss:  701MB ->  704MB (   +3MB)  write_allocator_module
time:   0.133; rss:  710MB ->  732MB (  +21MB)  codegen_to_LLVM_IR
time:   1.913; rss:  441MB ->  732MB ( +291MB)  codegen_crate
time:  12.927; rss:  732MB ->  608MB ( -124MB)  LLVM_passes
time:   0.001; rss:  608MB ->  604MB (   -4MB)  join_worker_thread
time:  12.893; rss:  536MB ->  604MB (  +68MB)  finish_ongoing_codegen
time:   0.046; rss:  604MB ->  445MB ( -159MB)  run_linker
time:   0.047; rss:  604MB ->  445MB ( -158MB)  link_binary
time:   0.047; rss:  604MB ->  445MB ( -158MB)  link_crate
time:   0.047; rss:  604MB ->  445MB ( -158MB)  link
time:  17.606; rss:   32MB ->  111MB (  +79MB)  total

upsuper added the C-bug Category: This is a bug. label Jun 12, 2021

rustbot added I-compilemem Issue: Problems and improvements with respect to memory usage during compilation. I-compiletime Issue: Problems and improvements with respect to compile times. T-compiler Relevant to the compiler team, which will review and decide on the PR/issue. labels Jun 12, 2021

nbdd0121 mentioned this issue Nov 1, 2021

Literally initializing [&str; N] (using proc macro) doesn't scale, rustc consumes huge amounts of time and RAM (stable and nightly) #90445

Closed

crlf0710 added the A-borrow-checker Area: The borrow checker label Nov 2, 2021

Mark-Simulacrum mentioned this issue Dec 2, 2021

Store liveness in interval sets for region inference #90637

Merged

Mark-Simulacrum mentioned this issue Jan 15, 2024

perf: Don't track specific live points for promoteds #120003

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Large memory usage and long time on compiling large number of println #86244

Large memory usage and long time on compiling large number of println #86244

upsuper commented Jun 12, 2021 •

edited

Loading

weiby3 commented Jun 12, 2021

oxalica commented Jun 12, 2021

inquisitivecrystal commented Jun 12, 2021 •

edited

Loading

nbdd0121 commented Jun 12, 2021

nbdd0121 commented Jun 12, 2021 •

edited

Loading

memoryruins commented Jun 16, 2021

nbdd0121 commented Jun 16, 2021

memoryruins commented Jun 16, 2021 •

edited

Loading

klensy commented Jan 16, 2025

Large memory usage and long time on compiling large number of println #86244

Large memory usage and long time on compiling large number of println #86244

Comments

upsuper commented Jun 12, 2021 • edited Loading

Meta

weiby3 commented Jun 12, 2021

oxalica commented Jun 12, 2021

inquisitivecrystal commented Jun 12, 2021 • edited Loading

nbdd0121 commented Jun 12, 2021

nbdd0121 commented Jun 12, 2021 • edited Loading

memoryruins commented Jun 16, 2021

nbdd0121 commented Jun 16, 2021

memoryruins commented Jun 16, 2021 • edited Loading

klensy commented Jan 16, 2025

upsuper commented Jun 12, 2021 •

edited

Loading

inquisitivecrystal commented Jun 12, 2021 •

edited

Loading

nbdd0121 commented Jun 12, 2021 •

edited

Loading

memoryruins commented Jun 16, 2021 •

edited

Loading