Closed ncoish closed 5 years ago
ncoish
commented
6 years ago This error has happened again twice in the past 2 days on our build machines. We are now on Stable 1.27.0.
thread 'main' panicked at 'specified instant was later than self', libcore\option.rs:914:5
note: Run with RUST_BACKTRACE=1 for a backtrace.
error: internal compiler error: unexpected panic
note: rustc 1.27.0 (3eda71b00 2018-06-19) running on i686-pc-windows-msvc
note: compiler flags: -C opt-level=3 --crate-type lib
ncoish
commented
6 years ago Regarding uptimes: On first observance the machines had been running for ~2 weeks. Second occurance: ~2 weeks Third occurance: ~2 days
I will try to set up a timing script to get a more precise time between compiler errors, but these numbers are ballpark.
paul-tcell
commented
6 years ago We're seeing this frequently
Compiling num-traits v0.1.43
Compiling syn v0.14.7
thread 'main' panicked at 'specified instant was later than self', libcore\option.rs:914:5
stack backtrace:
0: 0x7ffd61b15bd5 - <u128 as compiler_builtins::int::Int>::min_value::h9677a6134f517472
1: 0x7ffd61b1c1ff - core::alloc::<impl core::alloc::::Opaque>::null_mut::h5057fcb0fb4b9a64
2: 0x7ffd61b1a8b5 - std::panicking::take_hook::hec38ed21b43fe057
3: 0x7ffd61b1a4ec - std::panicking::take_hook::hec38ed21b43fe057
4: 0x7ffd5e06d439 - rustc::ty::structural_impls::<impl rustc::ty::context::Lift<'tcx> for rustc::middle::const_val::ErrKind<'a>>::lift_to_tcx::hcbea0cf3d5a4c41c
5: 0x7ffd61b1b06f - std::panicking::rust_panic_with_hook::hcd28e5dfec0e3af8
6: 0x7ffd61b1ab76 - std::panicking::begin_panic_fmt::hc5ca911ddece0631
7: 0x7ffd61b1ab2f - rust_begin_unwind
8: 0x7ffd61b5817c - core::panicking::panic_fmt::h4892ba3c15feb17f
9: 0x7ffd61b69b41 - core::option::expect_failed::h3e5561a5bf3400d7
10: 0x7ffd61b22260 - std::time::Instant::elapsed::ha0639ec21b19c6f8
11: 0x7ffd7bf5543b - <rustc_trans_utils::trans_crate::MetadataOnlyTransCrate as rustc_trans_utils::trans_crate::TransCrate>::provide_extern::h940466a7d74a5262
12: 0x7ffd7bf568a0 - rustc_trans_utils::symbol_names::provide::h0b93799f774cb512
13: 0x7ffd5e086032 - rustc::ty::maps::<impl rustc::ty::maps::config::QueryConfig<'tcx> for rustc::ty::maps::queries::symbol_name<'tcx>>::compute::h434d1f456a5dee7e
14: 0x7ffd5dbaa719 - rustc::dep_graph::graph::DepGraph::assert_ignored::hf7aea613bc733bb5
15: 0x7ffd5ddadb85 - rustc::ty::context::tls::track_diagnostic::h66cc7851580ae713
16: 0x7ffd5de030f3 - rustc::ty::maps::plumbing::<impl rustc::ty::context::TyCtxt<'a, 'gcx, 'tcx>>::try_mark_green_and_read::h1877c133479ca0e6
17: 0x7ffd5dedb79e - rustc::ty::maps::plumbing::<impl rustc::ty::context::TyCtxt<'a, 'gcx, 'tcx>>::try_mark_green_and_read::h1877c133479ca0e6
18: 0x7ffd5df1941c - rustc::ty::maps::<impl rustc::ty::context::TyCtxt<'a, 'tcx, 'lcx>>::symbol_name::he3fd5921efcfe7bb
19: 0x7ffd5715b47a - <rustc_trans::builder::Builder<'a, 'tcx> as core::ops::drop::Drop>::drop::h322d11a95248e30a
20: 0x7ffd570cebec - <rustc_trans::meth::VirtualIndex as core::fmt::Debug>::fmt::h3878f7ab587deb2c
21: 0x7ffd5704d5ee - LLVMRustThinLTOAvailable
22: 0x7ffd570f3062 - <rustc_trans::base::ValueIter as core::iter::iterator::Iterator>::next::h95403e2bead2716d
23: 0x7ffd5db8d485 - rustc::dep_graph::graph::DepGraph::assert_ignored::hf7aea613bc733bb5
24: 0x7ffd5dd7b961 - rustc::ty::context::tls::track_diagnostic::h66cc7851580ae713
25: 0x7ffd5ddfec27 - rustc::ty::maps::plumbing::<impl rustc::ty::context::TyCtxt<'a, 'gcx, 'tcx>>::try_mark_green_and_read::h1877c133479ca0e6
26: 0x7ffd5de8c18a - rustc::ty::maps::plumbing::<impl rustc::ty::context::TyCtxt<'a, 'gcx, 'tcx>>::try_mark_green_and_read::h1877c133479ca0e6
27: 0x7ffd571458ec - <rustc_trans::back::linker::WasmLd as rustc_trans::back::linker::Linker>::finalize::h807558c41ba955d3
28: 0x7ffd5db904f0 - rustc::dep_graph::graph::DepGraph::assert_ignored::hf7aea613bc733bb5
29: 0x7ffd5ddbbf07 - rustc::ty::context::tls::track_diagnostic::h66cc7851580ae713
30: 0x7ffd5de0ab73 - rustc::ty::maps::plumbing::<impl rustc::ty::context::TyCtxt<'a, 'gcx, 'tcx>>::try_mark_green_and_read::h1877c133479ca0e6
31: 0x7ffd5ded33bc - rustc::ty::maps::plumbing::<impl rustc::ty::context::TyCtxt<'a, 'gcx, 'tcx>>::try_mark_green_and_read::h1877c133479ca0e6
32: 0x7ffd60776b98 - <rustc_metadata::encoder::ImplVisitor<'a, 'tcx> as rustc::hir::itemlikevisit::ItemLikeVisitor<'v>>::visit_item::h6fbd8be0b12dc211
33: 0x7ffd6088cbaa - rustc_metadata::cstore_impl::<impl rustc::middle::cstore::CrateStore for rustc_metadata::cstore::CStore>::encode_metadata::hd842f9cf7949e0d3
34: 0x7ffd5df112fd - rustc::ty::context::TyCtxt::encode_metadata::hbb881fad4f945633
35: 0x7ffd570ef4aa - rustc_trans::base::trans_instance::h7f44600d98746c44
36: 0x7ffd56ff807a - <unknown>
37: 0x7ffd570efee0 - <rustc_trans::base::ValueIter as core::iter::iterator::Iterator>::next::h95403e2bead2716d
38: 0x7ffd5704324f - <rustc_trans::LlvmTransCrate as rustc_trans_utils::trans_crate::TransCrate>::trans_crate::he1ce52bc7ac27ad4
39: 0x7ffd61ecfff9 - rustc_driver::driver::build_output_filenames::hfe7c8d798b282910
40: 0x7ffd61ec2d1a - rustc_driver::driver::phase_4_translate_to_llvm::h6de8823c2b178633
41: 0x7ffd61f5ec1c - rustc_driver::profile::trace::write_style::h1440147d1e9aaf66
42: 0x7ffd61f59c94 - <humantime::duration::Error as std::error::Error>::cause::hda0dca1bca393eeb
43: 0x7ffd61f1ab22 - <rustc_driver::pretty::UserIdentifiedItem as core::fmt::Debug>::fmt::h299247c872c03d2d
44: 0x7ffd61e55788 - <unknown>
45: 0x7ffd61eb7a1c - rustc_driver::driver::compile_input::h01ffbfc578755e48
46: 0x7ffd61f65df3 - rustc_driver::run_compiler::hb5db22dd9e7f4b75
47: 0x7ffd61ed7b5e - rustc_driver::driver::build_output_filenames::hfe7c8d798b282910
48: 0x7ffd61e5ee20 - <unknown>
49: 0x7ffd61ed4f6e - rustc_driver::driver::build_output_filenames::hfe7c8d798b282910
50: 0x7ffd61b536b1 - _rust_maybe_catch_panic
51: 0x7ffd61f611d6 - rustc_driver::profile::trace::write_style::h1440147d1e9aaf66
52: 0x7ffd61f750fd - rustc_driver::main::h02399fb94c78baca
53: 0x7ff691921005 - <unknown>
54: 0x7ffd61b1aa76 - std::panicking::update_panic_count::h34d4460f41db263e
55: 0x7ffd61b536b1 - _rust_maybe_catch_panic
56: 0x7ffd61b156c5 - std::rt::lang_start_internal::h3f38d7833c8c1ec2
57: 0x7ff691921079 - <unknown>
58: 0x7ff691921298 - <unknown>
59: 0x7ffd89ce8363 - BaseThreadInitThunk
60: 0x7ffd8c6070d0 - RtlUserThreadStart
query stack during panic:
#0 [symbol_name] computing the symbol for `<u8 as roots::Roots>::sqrt::<i8, extern "rust-call" fn((u8,)) -> u8, &&u8>::{{closure}}`
#1 [collect_and_partition_translation_items] collect_and_partition_translation_items
#2 [exported_symbols] exported_symbols
end of query stack
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/blob/master/CONTRIBUTING.md#bug-reports
note: rustc 1.27.1 (5f2b325f6 2018-07-07) running on x86_64-pc-windows-msvc
note: compiler flags: -C debuginfo=2 --crate-type lib
note: some of the compiler flags provided by cargo are hidden
error: Could not compile `num-integer`.Another instance of this issue happening:
time: 2018-09-18 14:07:02.708000
invoking: cargo +stable-x86_64 build --release
in: c:\jenkins\workspace\SDK5\build-local-system\giles
Compiling slab v0.3.0
thread 'main' panicked at 'specified instant was later than self', libcore\option.rs:960:5
Compiling ucd-util v0.1.1
Compiling lazy_static v0.2.11
stack backtrace:
0: <std::sync::mpsc::select::Select as core::fmt::Debug>::fmt
1: std::stdsimd::arch::detect::os::check_for
2: std::panicking::take_hook
3: std::panicking::take_hook
4: <rustc::ty::query::on_disk_cache::CacheEncoder<'enc, 'a, 'tcx, serialize::opaque::Encoder<'enc>> as serialize::serialize::SpecializedEncoder<rustc::ich::fingerprint::Fingerprint>>::specialized_encode
5: std::panicking::rust_panic_with_hook
6: std::panicking::begin_panic_fmt
7: rust_begin_unwind
8: core::panicking::panic_fmt
9: core::option::expect_failed
10: <std::sys_common::process::DefaultEnvKey as core::fmt::Debug>::fmt
11: std::time::Instant::elapsed
12: <rustc_codegen_utils::codegen_backend::MetadataOnlyCodegenBackend as rustc_codegen_utils::codegen_backend::CodegenBackend>::join_codegen_and_link
13: rustc_codegen_utils::symbol_names::provide
14: rustc::ty::query::on_disk_cache::__ty_decoder_impl::<impl serialize::serialize::Decoder for rustc::ty::query::on_disk_cache::CacheDecoder<'a, 'tcx, 'x>>::read_str
15: rustc::ty::context::tls::track_diagnostic
16: rustc::dep_graph::graph::DepGraph::assert_ignored
17: rustc::ty::context::tls::track_diagnostic
18: rustc::ty::query::plumbing::<impl rustc::ty::context::TyCtxt<'a, 'gcx, 'tcx>>::try_print_query_stack
19: rustc::ty::query::plumbing::<impl rustc::ty::context::TyCtxt<'a, 'gcx, 'tcx>>::try_print_query_stack
20: rustc::ty::query::<impl rustc::ty::context::TyCtxt<'a, 'tcx, 'lcx>>::symbol_name
21: <rustc_codegen_llvm::back::write::MainThreadWorkerState as core::fmt::Debug>::fmt
22: <rustc_codegen_llvm::debuginfo::create_scope_map::MirDebugScope as core::fmt::Debug>::fmt
23: <rustc_codegen_llvm::back::link::exec_linker::Escape<'a> as core::fmt::Display>::fmt
24: <rustc_codegen_llvm::base::ValueIter as core::iter::iterator::Iterator>::next
25: rustc::ty::context::tls::track_diagnostic
26: rustc::dep_graph::graph::DepGraph::assert_ignored
27: rustc::ty::context::tls::track_diagnostic
28: rustc::ty::query::plumbing::<impl rustc::ty::context::TyCtxt<'a, 'gcx, 'tcx>>::try_print_query_stack
29: rustc::ty::query::plumbing::<impl rustc::ty::context::TyCtxt<'a, 'gcx, 'tcx>>::try_print_query_stack
30: <rustc_codegen_llvm::base::ValueIter as core::iter::iterator::Iterator>::next
31: <rustc_codegen_llvm::LlvmCodegenBackend as rustc_codegen_utils::codegen_backend::CodegenBackend>::codegen_crate
32: rustc_driver::driver::build_output_filenames
33: rustc_driver::driver::phase_4_codegen
34: rustc_driver::profile::dump
35: <rustc_driver::derive_registrar::Finder as rustc::hir::itemlikevisit::ItemLikeVisitor<'v>>::visit_impl_item
36: <rustc_driver::pretty::IdentifiedAnnotation<'hir> as rustc_driver::pretty::PrinterSupport>::sess
37: <unknown>
38: rustc_driver::driver::compile_input
39: rustc_driver::run_compiler
40: rustc_driver::target_features::add_configuration
41: <rustc_driver::pretty::IdentifiedAnnotation<'hir> as rustc_driver::pretty::PrinterSupport>::sess
42: _rust_maybe_catch_panic
43: <rustc_driver::derive_registrar::Finder as rustc::hir::itemlikevisit:: 44: rustc_driver::main
45: <unknown>
46: std::panicking::update_panic_count
47: _rust_maybe_catch_panic
48: std::rt::lang_start_internal
49: <unknown>
50: <unknown>
51: BaseThreadInitThunk
52: RtlUserThreadStart
query stack during panic:
#0 [symbol_name] computing the symbol for `<alloc::btree::node::Handle<alloc::btree::node::NodeRef<BorrowType, K, V, NodeType>, HandleType>><alloc::btree::node::marker::Owned, std::sys::windows::process::WindowsEnvKey, std::option::Option<std::ffi::OsString>, alloc::btree::node::marker::Leaf, alloc::btree::node::marker::KV>::reborrow`
#1 [collect_and_partition_mono_items] collect_and_partition_mono_items
end of query stack
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/blob/master/CONTRIBUTING.md#bug-reports
note: rustc 1.28.0 (9634041f0 2018-07-30) running on x86_64-pc-windows-msvc
note: compiler flags: -C opt-level=3 --crate-type bin
note: some of the compiler flags provided by cargo are hidden
michaelwoerister
commented
5 years ago @wesleywiser, might this have to do with the self-profiler? It looks like timing on Windows is flaky (maybe it's not using the high-resolution timer by default?). Or there's a bug in the timing code? If it's a flaky timer, it should be easy to not panic (and instead just record a zero-length interval).
wesleywiser
commented
5 years ago @michaelwoerister Yes, it looks like the issue is this line in the self profiler:
What's interesting is that the docs for Instant claim that this shouldn't be able to happen:
A measurement of a monotonically nondecreasing clock. Opaque and useful only with Duration.
Instants are always guaranteed to be no less than any previously measured instant when created, and are often useful for tasks such as measuring benchmarks or timing how long an operation takes.
Note, however, that instants are not guaranteed to be steady. In other words, each tick of the underlying clock may not be the same length (e.g. some seconds may be longer than others). An instant may jump forwards or experience time dilation (slow down or speed up), but it will never go backwards.
michaelwoerister
commented
5 years ago @wesleywiser Yes, it certainly looks that way. Might be a bug in the Windows implementation for this method (@rust-lang/libs). If that turns out hard to fix, we might have to work around it. Something like:
let now = Instant::now();
let elapsed = if self.current_timer >= now {
Duration::new(0,0)
} else {
self.current_timer.elapsed()
};
self.current_timer = now;
nagisa
commented
5 years ago While Instant::new not returning monotonically increasing times seems like ultimately a T-libs issue, it would also be good to find out what changed in the compiler to start causing this and perhaps to implement a workaround (in the compiler).
@wesleywiser want to take a look at implementing a work-around in the compiler?
We should also fill a separate issue for T-libs.
SimonSapin
commented
5 years ago elapsed is just Instant::now() - *self, and instant subtraction panics on underflow. now on Windows is:
https://msdn.microsoft.com/en-us/library/windows/desktop/ms644904(v=vs.85).aspx links to https://docs.microsoft.com/en-us/windows/desktop/SysInfo/acquiring-high-resolution-time-stamps which says:
Is the performance counter monotonic (non-decreasing)?
Yes
Which suggests this panic should not happen.
But also:
When you compare performance counter results that are acquired from different threads, consider values that differ by ± 1 tick to have an ambiguous ordering. If the time stamps are taken from the same thread, this ± 1 tick uncertainty doesn't apply.
Was self.current_timer obtained on a different thread than elapsed() runs on?
estebank
commented
5 years ago I would like to put that code behind a cfg with a comment, to make it painfully obvious its a work around.
alexcrichton
commented
5 years ago It's also worth pointing out that the +/- one tick is in theroy handled here, regardless of where it happens or not.
wesleywiser
commented
5 years ago @michaelwoerister That seems reasonable to me.
@nagisa Yes, I'll work on that today if I get some time around the holiday. I think the best thing would be a two-pronged approach:
Disable the self-profiler unless it's requested. We didn't do this initially because the measured performance overhead was microscopic. However, making it opt-in would, IMO, significantly lower the impact of this issue.
Explicitly detect the case where where elapsed would be negative and handle that like @michaelwoerister suggests.
@estebank Agreed. Will do.
@alexcrichton Interesting. Perhaps the delta is greater than 1 tick for some reason?
ncoish
commented
5 years ago I'm glad to see there's a potential fix! For what it's worth this seems to be very hardware dependent: After moving to a t2.2xlarge AWS instance the problem was still happening, but since upgrading to t3.2xlarge, the problem has not recurred.
wesleywiser
commented
5 years ago I guess there's still a question for @rust-lang/libs: should we pursue a fix or change in in the Instant api?
I left a comment here with some additional findings. This doesn't appear to be strictly a Windows issue. For example, #49281 shows the same issue on Linux/arm64 and #48514 shows the same issue on OpenBSD.
alexcrichton
commented
5 years ago Oh right yeah thanks for the prod @wesleywiser, I've opened https://github.com/rust-lang/rust/pull/56988 as it seems like the "best" way to go from here
After ~2 weeks of continuously building our project without fail, our Windows build machines (2 of them) began throwing an error of this kind, while building dependencies:
Each time this failure occurred it was on a different dependency of the project. It's also worth noting that this failure did not occur on every build, but it was very frequent. The failure occurs using both
i686-pc-windows-msvcandx86_64-pc-windows-msvc.A very similar issue was reported in rustc 1.23.0: https://github.com/rust-lang/rust/issues/47684
Restarting the affected build machines seems to have stopped the issue from occurring, at least temporarily.
If there's anything I can do to help diagnose/solve this problem, I'm eager to jump in.
Meta
rustc --version --verbose: rustc 1.26.2 (594fb253c 2018-06-01) binary: rustc commit-hash: 594fb253c2b02b320c728391a425d028e6dc7a09 commit-date: 2018-06-01 host: i686-pc-windows-msvc release: 1.26.2 LLVM version: 6.0Backtrace:
and the relevant output of systeminfo: