Slow backtrace on panic, nightly 2017-05-28 #42295
Description
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