Slow backtrace on panic, nightly 2017-05-28

[koivunej]

I recently noticed that my app startup is much slower on --release builds than on debug builds. Starting my app on an empty data directory triggers an error which is mapped into an error_chain type. In this issue I am showing backtraces from a startup which fails instantly at the first file open which I modified to use unwrap() instead of errors.

I have debug = true for [profile.release] in my Cargo.toml. I initially suspected this was a bug with error_chain, but this problem manifests even with when bypassing error_chain and calling unwrap directly to panic.

When panicking, all other frames are printed fast, but the following (full backtraces in the end):

  10: <core::iter::Map<I, F> as core::iter::iterator::Iterator>::next
             at /checkout/src/libcore/result.rs:737
             at src/db/checkpoint.rs:183
             at /checkout/src/libcore/ops.rs:2633
             at /checkout/src/libcore/ops.rs:2731
             at /checkout/src/libcore/option.rs:398
             at /checkout/src/libcore/iter/mod.rs:1065
             at /checkout/src/libcore/iter/mod.rs:1065

First line of output above takes a bit longer to output, but the at /checkout/src/libcore/result:737 takes more than ten seconds to print. After that the rest of the output is instant.

There is a possibly related rustc issue #37477. When profiling with perf record -g --call-graph dwarf -F 555 the outermost ("Children") 96% of time goes to read_function_entry and the most self time is used by __rbt_backtrace_alloc.

There is no problem when RUST_BACKTRACE=0 or when running non-optimized binary (Cargo settings for dev profile are the defaults).

Timings

$ time RUST_BACKTRACE=0 cargo run --release &>/dev/null
real    0m0.361s
user    0m0.288s
sys     0m0.064s
$ time RUST_BACKTRACE=1 cargo run --release &>/dev/null
real    0m22.380s
user    0m22.216s
sys     0m0.144s
$ time RUST_BACKTRACE=0 cargo run &>/dev/null
real    0m0.301s
user    0m0.260s
sys     0m0.032s
$ time RUST_BACKTRACE=1 cargo run &>/dev/null
real    0m0.899s
user    0m0.828s
sys     0m0.060s

I tried this code: I have been unable to produce a minimized example and my current code base is not open source. My --release optimized binary is 44M and I link to a pretty high number (~37) of crates. Suggestions on generating a minimized test case are welcome, though I suspect it is required to have a large binary.

I expected to see this happen: Fast backtrace

Instead, this happened: Slow backtrace (20s compared to 0.3s)

Meta

rustc --version --verbose:

rustc 1.19.0-nightly (d47cf08d5 2017-05-28)
binary: rustc
commit-hash: d47cf08d57d881f34f9724edfb0b3b93209af202
commit-date: 2017-05-28
host: x86_64-unknown-linux-gnu
release: 1.19.0-nightly
LLVM version: 4.0

$ env | grep -e RUSTFLAGS -e CARGO_INCREMENTAL
RUSTFLAGS=
CARGO_INCREMENTAL=0

First noticed with rustc 1.19.0-nightly (5f3966864 2017-05-25), then upgraded to latest. Same behaviour when gold is used as linker. Same behaviour with incremental compilation.

Backtrace is slow also with rustc 1.18.0-nightly (2564711e8 2017-04-04).

Backtrace: without `--release`

thread '<unnamed>' panicked at 'called `Result::unwrap()` on an `Err` value: Error { repr: Os { code: 13, message: "Permission denied" } }', /checkout/src/libcore/result.rs:859
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
stack backtrace:
   0: std::sys::imp::backtrace::tracing::imp::unwind_backtrace
             at /checkout/src/libstd/sys/unix/backtrace/tracing/gcc_s.rs:49
   1: std::sys_common::backtrace::_print
             at /checkout/src/libstd/sys_common/backtrace.rs:71
   2: std::panicking::default_hook::{{closure}}
             at /checkout/src/libstd/sys_common/backtrace.rs:60
             at /checkout/src/libstd/panicking.rs:355
   3: std::panicking::default_hook
             at /checkout/src/libstd/panicking.rs:371
   4: std::panicking::rust_panic_with_hook
             at /checkout/src/libstd/panicking.rs:549
   5: std::panicking::begin_panic
             at /checkout/src/libstd/panicking.rs:511
   6: std::panicking::begin_panic_fmt
             at /checkout/src/libstd/panicking.rs:495
   7: rust_begin_unwind
             at /checkout/src/libstd/panicking.rs:471
   8: core::panicking::panic_fmt
             at /checkout/src/libcore/panicking.rs:69
   9: core::result::unwrap_failed
             at /checkout/src/libcore/macros.rs:29
  10: <core::result::Result<T, E>>::unwrap
             at /checkout/src/libcore/result.rs:737
  11: txeng::db::checkpoint::FileCheckpoint::open_or_create
             at src/db/checkpoint.rs:183
  12: core::ops::FnMut::call_mut
             at /checkout/src/libcore/ops.rs:2633
  13: core::ops::impls::<impl core::ops::FnOnce<A> for &'a mut F>::call_once
             at /checkout/src/libcore/ops.rs:2731
  14: <core::option::Option<T>>::map
             at /checkout/src/libcore/option.rs:398
  15: <core::iter::Map<I, F> as core::iter::iterator::Iterator>::next
             at /checkout/src/libcore/iter/mod.rs:1065
  16: <core::iter::Map<I, F> as core::iter::iterator::Iterator>::next
             at /checkout/src/libcore/iter/mod.rs:1065
  17: <txeng::db::Database<T>>::open_or_create
             at src/db/mod.rs:265
  18: txeng::node::serve
             at src/node/mod.rs:160
  19: txeng::node::spawn::{{closure}}
             at src/node/mod.rs:52

Backtrace with `--release`

thread '<unnamed>' panicked at 'called `Result::unwrap()` on an `Err` value: Error { repr: Os { code: 13, message: "Permission denied" } }', /checkout/src/libcore/result.rs:859
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
stack backtrace:
   0: std::sys::imp::backtrace::tracing::imp::unwind_backtrace
             at /checkout/src/libstd/sys/unix/backtrace/tracing/gcc_s.rs:49
   1: std::sys_common::backtrace::_print
             at /checkout/src/libstd/sys_common/backtrace.rs:71
   2: std::panicking::default_hook::{{closure}}
             at /checkout/src/libstd/sys_common/backtrace.rs:60
             at /checkout/src/libstd/panicking.rs:355
   3: std::panicking::default_hook
             at /checkout/src/libstd/panicking.rs:371
   4: std::panicking::rust_panic_with_hook
             at /checkout/src/libstd/panicking.rs:549
   5: std::panicking::begin_panic
             at /checkout/src/libstd/panicking.rs:511
   6: std::panicking::begin_panic_fmt
             at /checkout/src/libstd/panicking.rs:495
   7: rust_begin_unwind
             at /checkout/src/libstd/panicking.rs:471
   8: core::panicking::panic_fmt
             at /checkout/src/libcore/panicking.rs:69
   9: core::result::unwrap_failed
             at /checkout/src/libcore/macros.rs:29
  10: <core::iter::Map<I, F> as core::iter::iterator::Iterator>::next
             at /checkout/src/libcore/result.rs:737
             at src/db/checkpoint.rs:183
             at /checkout/src/libcore/ops.rs:2633
             at /checkout/src/libcore/ops.rs:2731
             at /checkout/src/libcore/option.rs:398
             at /checkout/src/libcore/iter/mod.rs:1065
             at /checkout/src/libcore/iter/mod.rs:1065
  11: <txeng::db::Database<T>>::open_or_create
             at src/db/mod.rs:265
  12: txeng::node::serve
             at src/node/mod.rs:160

diff -u dev.backtrace release.backtrace

--- dev.backtrace       2017-05-29 16:39:08.335927763 +0300
+++ release.backtrace   2017-05-29 16:39:09.419952077 +0300
@@ -22,23 +22,15 @@
              at /checkout/src/libcore/panicking.rs:69
    9: core::result::unwrap_failed
              at /checkout/src/libcore/macros.rs:29
-  10: <core::result::Result<T, E>>::unwrap
+  10: <core::iter::Map<I, F> as core::iter::iterator::Iterator>::next
              at /checkout/src/libcore/result.rs:737
-  11: txeng::db::checkpoint::FileCheckpoint::open_or_create
              at src/db/checkpoint.rs:183
-  12: core::ops::FnMut::call_mut
              at /checkout/src/libcore/ops.rs:2633
-  13: core::ops::impls::<impl core::ops::FnOnce<A> for &'a mut F>::call_once
              at /checkout/src/libcore/ops.rs:2731
-  14: <core::option::Option<T>>::map
              at /checkout/src/libcore/option.rs:398
-  15: <core::iter::Map<I, F> as core::iter::iterator::Iterator>::next
              at /checkout/src/libcore/iter/mod.rs:1065
-  16: <core::iter::Map<I, F> as core::iter::iterator::Iterator>::next
              at /checkout/src/libcore/iter/mod.rs:1065
-  17: <txeng::db::Database<T>>::open_or_create
+  11: <txeng::db::Database<T>>::open_or_create
              at src/db/mod.rs:265
-  18: txeng::node::serve
+  12: txeng::node::serve
              at src/node/mod.rs:160
-  19: txeng::node::spawn::{{closure}}
-             at src/node/mod.rs:52

Can you show the output of these two(assuming shell is bash):

$ time RUST_BACKTRACE=1 rustc -vv
$ time RUST_BACKTRACE=0 rustc -vv

(-vv is not a typo for -vV)

[koivunej]

With some nightly I had installed:

$ rustc -V
rustc 1.19.0-nightly (258ae6dd9 2017-06-15)

$ time RUST_BACKTRACE=1 rustc -vv
error: Option 'verbose' given more than once.
real    0m0.762s
user    0m0.392s
sys     0m0.052s

$ time RUST_BACKTRACE=0 rustc -vv
error: Option 'verbose' given more than once.
real    0m0.231s
user    0m0.048s
sys     0m0.176s

For the nightly I reported the bug against:

$ time RUST_BACKTRACE=1 ~/.rustup/toolchains/nightly-2017-05-28-x86_64-unknown-linux-gnu/bin/rustc -vv
error: Option 'verbose' given more than once.
real    0m0.263s
user    0m0.236s
sys     0m0.020s

$ time RUST_BACKTRACE=0 ~/.rustup/toolchains/nightly-2017-05-28-x86_64-unknown-linux-gnu/bin/rustc -vv
error: Option 'verbose' given more than once.
real    0m0.060s
user    0m0.056s
sys     0m0.004s

Just noticed that rustup might be adding some here as well:

$ time RUST_BACKTRACE=1 rustup run nightly-2017-05-28 rustc -vv
error: Option 'verbose' given more than once.
real    0m0.339s
user    0m0.324s
sys     0m0.012s

$ time RUST_BACKTRACE=0 rustup run nightly-2017-05-28 rustc -vv
error: Option 'verbose' given more than once.
real    0m0.063s
user    0m0.048s
sys     0m0.008s

For stable 1.18:

$ rustup run stable rustc -V
rustc 1.18.0 (03fc9d622 2017-06-06)

$ time RUST_BACKTRACE=1 rustup run stable rustc -vv
error: Option 'verbose' given more than once.
real    0m0.439s
user    0m0.288s
sys     0m0.144s

$ time RUST_BACKTRACE=0 rustup run stable rustc -vv
error: Option 'verbose' given more than once.
real    0m0.056s
user    0m0.036s
sys     0m0.012s

$ time RUST_BACKTRACE=1 ~/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/bin/rustc -vv
error: Option 'verbose' given more than once.
real    0m0.260s
user    0m0.164s
sys     0m0.092s

$ time RUST_BACKTRACE=0 ~/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/bin/rustc -vv
error: Option 'verbose' given more than once.
real    0m0.106s
user    0m0.032s
sys     0m0.068s

I think you were right, this seems to be the issue: #37477 (comment)

EDIT: I'm actually basing all this on your OP, not on what I asked above. (re below)

[koivunej]

@xftroxgpx just to clarify. I encountered this while running my own code, not having rustc errors.

In the end it'd seem plausible that the gcc/libbacktrace bug would be cause. If I understand correctly, slower rustc errors were fixed by stripping the debuginfo but that is not a viable solution if I want to run my code in production with backtraces.

Apparently a possible solution could be the removal of mmap.c functionality and thus forcing the use of malloc. I think I'd need to compile a custom rustc to be able to test this to confirm how it works with my codebase?

EDIT: linked to the bug confirming comment by wthrowe

[steveklabnik]

@koivunej are you still seeing this today? any chance of a reproduction?

[koivunej]

@steveklabnik I haven't touched this old codebase in some 2-3 years :) Thanks for pinging me though, I had hoped this was already fixed. I'll look into reproducing this and reopen if I can make this happen.

Looking at #29293 the merge of #45523 should had fixed this, closing as the 29293 is already closed.