Crash while running compiler with self profile

[weiznich]

Code

https://github.com/Ten0/diesel_3223_repro

Meta

I'm trying to debug an issue with extensive compile times in diesel. While running the compiler on an example with RUSTFLAGS="-Z self-profile -Z self-profile-events=default,args" I've got the following ICE, which prompt me to report it here.

rustc --version --verbose:

rustc 1.64.0-nightly (87588a2af 2022-07-13)
binary: rustc
commit-hash: 87588a2afd9ca903366f0deaf84d805f34469384
commit-date: 2022-07-13
host: x86_64-unknown-linux-gnu
release: 1.64.0-nightly
LLVM version: 14.0.6

Backtrace

hread 'rustc' panicked at 'called `Option::unwrap()` on a `None` value', /cargo/registry/src/git.luolix.top-1ecc6299db9ec823/measureme-10.0.0/src/stringtable.rs:105:18
stack backtrace:
   0:     0x7fd547ea2850 - std::backtrace_rs::backtrace::libunwind::trace::h546e34b136647819
                               at /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   1:     0x7fd547ea2850 - std::backtrace_rs::backtrace::trace_unsynchronized::h76e576fe0a1ec65e
                               at /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:     0x7fd547ea2850 - std::sys_common::backtrace::_print_fmt::h3489fbb9d5d01094
                               at /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/std/src/sys_common/backtrace.rs:66:5
   3:     0x7fd547ea2850 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h401cfc97a3c2f247
                               at /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/std/src/sys_common/backtrace.rs:45:22
   4:     0x7fd547efbe2c - core::fmt::write::h327c921ac5532dc9
                               at /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/core/src/fmt/mod.rs:1198:17
   5:     0x7fd547e93e15 - std::io::Write::write_fmt::h334c1fe5d85b41a9
                               at /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/std/src/io/mod.rs:1672:15
   6:     0x7fd547ea54e1 - std::sys_common::backtrace::_print::hddc5656bc817cc55
                               at /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/std/src/sys_common/backtrace.rs:48:5
   7:     0x7fd547ea54e1 - std::sys_common::backtrace::print::h46adcb0dcb6fbe81
                               at /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/std/src/sys_common/backtrace.rs:35:9
   8:     0x7fd547ea54e1 - std::panicking::default_hook::{{closure}}::h7e55301ce91fa17d
                               at /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/std/src/panicking.rs:295:22
   9:     0x7fd547ea51b3 - std::panicking::default_hook::he24b412fa8dea167
                               at /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/std/src/panicking.rs:314:9
  10:     0x7fd548747e04 - rustc_driver[24990f24c5f9557a]::DEFAULT_HOOK::{closure#0}::{closure#0}
  11:     0x7fd547ea5cb6 - std::panicking::rust_panic_with_hook::hd6be56b55800f278
                               at /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/std/src/panicking.rs:702:17
  12:     0x7fd547ea5ac9 - std::panicking::begin_panic_handler::{{closure}}::h299e1cde9b2d55bf
                               at /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/std/src/panicking.rs:586:13
  13:     0x7fd547ea2d34 - std::sys_common::backtrace::__rust_end_short_backtrace::h217affeadc688779
                               at /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/std/src/sys_common/backtrace.rs:138:18
  14:     0x7fd547ea5832 - rust_begin_unwind
                               at /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/std/src/panicking.rs:584:5
  15:     0x7fd547e69b73 - core::panicking::panic_fmt::hce80afc1c6c77893
                               at /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/core/src/panicking.rs:142:14
  16:     0x7fd547e69a3d - core::panicking::panic::h3f12aada7d8b1473
                               at /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/core/src/panicking.rs:48:5
  17:     0x7fd549a31b17 - <measureme[c6f461ac47bcd418]::stringtable::StringTableBuilder>::alloc::<[measureme[c6f461ac47bcd418]::stringtable::StringComponent; 3usize]>
  18:     0x7fd549a32220 - <measureme[c6f461ac47bcd418]::event_id::EventIdBuilder>::from_label_and_arg
  19:     0x7fd548fc46d8 - <rustc_data_structures[c8ca60dcaf2fb48e]::profiling::SelfProfilerRef>::with_profiler::<rustc_query_impl[99bc284093ae976]::profiling_support::alloc_self_profile_query_strings_for_query_cache<rustc_query_system[598ba4569291698b]::query::caches::DefaultCache<rustc_middle[911aaa7bc28cd14c]::infer::canonical::Canonical<rustc_middle[911aaa7bc28cd14c]::ty::ParamEnvAnd<rustc_middle[911aaa7bc28cd14c]::ty::sty::ProjectionTy>>, core[734affb1a3eaf053]::result::Result<&rustc_middle[911aaa7bc28cd14c]::infer::canonical::Canonical<rustc_middle[911aaa7bc28cd14c]::infer::canonical::QueryResponse<rustc_middle[911aaa7bc28cd14c]::traits::query::NormalizationResult>>, rustc_middle[911aaa7bc28cd14c]::traits::query::NoSolution>>>::{closure#0}>
  20:     0x7fd54ae2bc1d - rustc_query_impl[99bc284093ae976]::profiling_support::alloc_self_profile_query_strings
  21:     0x7fd54a8ea732 - <rustc_interface[d9e16a24b5464548]::interface::Compiler>::enter::<rustc_driver[24990f24c5f9557a]::run_compiler::{closure#1}::{closure#2}, core[734affb1a3eaf053]::result::Result<core[734affb1a3eaf053]::option::Option<rustc_interface[d9e16a24b5464548]::queries::Linker>, rustc_errors[7a9b9cc96f052d83]::ErrorGuaranteed>>
  22:     0x7fd54a8e676f - rustc_span[b8cb56592c4d9b67]::with_source_map::<core[734affb1a3eaf053]::result::Result<(), rustc_errors[7a9b9cc96f052d83]::ErrorGuaranteed>, rustc_interface[d9e16a24b5464548]::interface::create_compiler_and_run<core[734affb1a3eaf053]::result::Result<(), rustc_errors[7a9b9cc96f052d83]::ErrorGuaranteed>, rustc_driver[24990f24c5f9557a]::run_compiler::{closure#1}>::{closure#1}>
  23:     0x7fd54a902880 - rustc_interface[d9e16a24b5464548]::interface::create_compiler_and_run::<core[734affb1a3eaf053]::result::Result<(), rustc_errors[7a9b9cc96f052d83]::ErrorGuaranteed>, rustc_driver[24990f24c5f9557a]::run_compiler::{closure#1}>
  24:     0x7fd54a916a02 - <scoped_tls[93927b52d599628f]::ScopedKey<rustc_span[b8cb56592c4d9b67]::SessionGlobals>>::set::<rustc_interface[d9e16a24b5464548]::interface::run_compiler<core[734affb1a3eaf053]::result::Result<(), rustc_errors[7a9b9cc96f052d83]::ErrorGuaranteed>, rustc_driver[24990f24c5f9557a]::run_compiler::{closure#1}>::{closure#0}, core[734affb1a3eaf053]::result::Result<(), rustc_errors[7a9b9cc96f052d83]::ErrorGuaranteed>>
  25:     0x7fd54a8e8cff - std[66dc708de7974585]::sys_common::backtrace::__rust_begin_short_backtrace::<rustc_interface[d9e16a24b5464548]::util::run_in_thread_pool_with_globals<rustc_interface[d9e16a24b5464548]::interface::run_compiler<core[734affb1a3eaf053]::result::Result<(), rustc_errors[7a9b9cc96f052d83]::ErrorGuaranteed>, rustc_driver[24990f24c5f9557a]::run_compiler::{closure#1}>::{closure#0}, core[734affb1a3eaf053]::result::Result<(), rustc_errors[7a9b9cc96f052d83]::ErrorGuaranteed>>::{closure#0}, core[734affb1a3eaf053]::result::Result<(), rustc_errors[7a9b9cc96f052d83]::ErrorGuaranteed>>
  26:     0x7fd54a902cd9 - <<std[66dc708de7974585]::thread::Builder>::spawn_unchecked_<rustc_interface[d9e16a24b5464548]::util::run_in_thread_pool_with_globals<rustc_interface[d9e16a24b5464548]::interface::run_compiler<core[734affb1a3eaf053]::result::Result<(), rustc_errors[7a9b9cc96f052d83]::ErrorGuaranteed>, rustc_driver[24990f24c5f9557a]::run_compiler::{closure#1}>::{closure#0}, core[734affb1a3eaf053]::result::Result<(), rustc_errors[7a9b9cc96f052d83]::ErrorGuaranteed>>::{closure#0}, core[734affb1a3eaf053]::result::Result<(), rustc_errors[7a9b9cc96f052d83]::ErrorGuaranteed>>::{closure#1} as core[734affb1a3eaf053]::ops::function::FnOnce<()>>::call_once::{shim:vtable#0}
  27:     0x7fd547eaf703 - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::h332a3f23c5b3d8bc
                               at /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/alloc/src/boxed.rs:1934:9
  28:     0x7fd547eaf703 - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::h33b3da7f4496df00
                               at /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/alloc/src/boxed.rs:1934:9
  29:     0x7fd547eaf703 - std::sys::unix::thread::Thread::new::thread_start::hf48274d01b2ded65
                               at /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/std/src/sys/unix/thread.rs:108:17
  30:     0x7fd547c6cb43 - start_thread
                               at ./nptl/./nptl/pthread_create.c:442:8
  31:     0x7fd547cfea00 - clone3
                               at ./misc/../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
  32:                0x0 - <unknown>
error: internal compiler error: unexpected panic

note: the compiler unexpectedly panicked. this is a bug.

note: we would appreciate a bug report: https://github.com/rust-lang/rust/issues/new?labels=C-bug%2C+I-ICE%2C+T-compiler&template=ice.md

note: rustc 1.64.0-nightly (87588a2af 2022-07-13) running on x86_64-unknown-linux-gnu

note: compiler flags: --crate-type lib -C embed-bitcode=no -C debuginfo=2 -Z self-profile -Z self-profile-events=default,args

note: some of the compiler flags provided by cargo are hidden

query stack during panic:
end of query stack
error: could not compile `diesel`

[lqd]

This is unfortunate but somewhat known for bigger crates, there's more than a u32's worth of strings or similar, e.g. rust-lang/measureme#165 or rust-lang/measureme#196

Maybe we should switch to a u64 🤡. There's no wg-self-profile GH team so I'll just cc the team members directly @wesleywiser @michaelwoerister in case they have a preference on how to fix this, and I'd look at doing that.

[Mark-Simulacrum]

I've not fully grasped the code yet, but it looks like there's a constant here that's significantly less than u32::MAX -- 100 million. Is that perhaps the limit we're actually hitting?

It seems a little unlikely to me that we're actually seeing u32::MAX unique(?) string IDs in a compilation that will succeed -- presumably, each of those strings is at least several bytes long, which quickly adds up to several dozen gigabytes of memory usage, right? I guess that makes some sense for very slow compilations....

If bumping to u64 isn't a large memory/performance regression, that seems an OK out here, but I'll also suggest that we could consider just giving up on allocating new strings but not panicking? I'm still a little surprised that we run up against a u32::MAX limit...

[lqd]

I haven't grasped the code either, and don't know yet what this 100 million cutoff between "virtual string ids" and "real string ids" means, or why this addition overflows after adding that value. It could for sure be a different issue than there being so many unique strings.

Maybe that 100 million base is somehow added multiple times through a different codepath than the expected checked_sub.

I'll try to investigate.

[lqd]

Ok that makes more sense: IIUC some of the StringIds (the regular string ids) are addressing a data stream (the StringTable) with a u32, and the overflow would then happen if that stream would get bigger than 4GB worth of strings ?

[michaelwoerister]

IIUC some of the StringIds (the regular string ids) are addressing a data stream (the StringTable) with a u32, and the overflow would then happen if that stream would get bigger than 4GB worth of strings ?

Yes, that sounds right.

Increasing the size of StringId will also increase the size of RawEvent (which is the main data structure that self-profiling emits) from 24 bytes to 32 bytes. That's probably acceptable.

Any optimizations to allow for a bigger string address space while keeping StringId at 4 bytes are probably not worth the additional implementation complexity.

[lqd]

Another way to (temporarily) go at this could be to reduce the size of the strings that rustc records: maybe some of the args' debug output is recorded (and/or some of the Display impls can be verbose, looking more like Debug impls) and those outliers push this case over the limit.

Maybe we can make these more compact, while retaining the key information (of course, until another bigger crate then overflows this compact output and we have to go to usizes anyways). It could also make these args more readable for people.

Here's an example of such a slightly verbose case, from Amos' recent article:

[eddyb]

Increasing the size of StringId will also increase the size of RawEvent (which is the main data structure that self-profiling emits) from 24 bytes to 32 bytes. That's probably acceptable.

IMO we should probably be forcing a pow2 size, and aligning things to the start of a page, to not end up e.g. straddling cache lines randomly and whatnot - though the impact is probably minimal either way.

[smklein]

I made an attempt at fixing this issue in rust-lang/measureme#216 , and would appreciate feedback!

[michaelwoerister]

We merged @smklein's fix, extending the StringId size to 64 bits. We'll need to update perf.rlos version of measureme before updating the compiler.