ICE rustc 1.26.2 'specified instant was later than self'

[ncoish]

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:

thread 'rustc' panicked at 'specified instant was later than self', libcore\option.rs:916:5

 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.26.2 (594fb253c 2018-06-01) running on i686-pc-windows-msvc
 
 note: compiler flags: -C opt-level=3 --crate-type lib
 
 note: some of the compiler flags provided by cargo are hidden
 
 error: Could not compile `ws`.

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-msvc and x86_64-pc-windows-msvc.

A very similar issue was reported in rustc 1.23.0: #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 (594fb25 2018-06-01)
binary: rustc
commit-hash: 594fb25
commit-date: 2018-06-01
host: i686-pc-windows-msvc
release: 1.26.2
LLVM version: 6.0

Backtrace:

    0: <i32 as std::sys::windows::net::IsMinusOne>::is_minus_one
    1: std::panicking::take_hook
    2: std::panicking::take_hook
    3: rustc::ty::maps::on_disk_cache::__ty_decoder_impl::<impl serialize::serialize::Decoder for rustc::ty::maps::on_disk_cache::CacheDecoder<'a, 'tcx, 'x>>::read_str
    4: std::panicking::begin_panic_fmt
    5: rust_begin_unwind
    6: core::panicking::panic_fmt
    7: core::option::expect_failed
    8: <std::ffi::c_str::IntoStringError as core::fmt::Debug>::fmt
    9: std::time::Instant::elapsed
   10: rustc_trans_utils::link::invalid_output_for_target
   11: rustc_trans_utils::symbol_names::provide
   12: rustc::dep_graph::graph::DepGraph::assert_ignored
   13: rustc::ty::maps::<impl rustc::ty::maps::queries::wasm_import_module_map<'tcx>>::try_get
   14: <rustc::ty::context::TyCtxt<'a, 'gcx, 'tcx> as rustc::ty::layout::HasTyCtxt<'gcx>>::tcx
   15: rustc::ty::maps::<impl rustc::ty::maps::queries::symbol_name<'tcx>>::ensure
   16: rustc::ty::maps::<impl rustc::ty::maps::queries::symbol_name<'tcx>>::try_get
   17: rustc::ty::maps::TyCtxtAt::symbol_name
   18: rustc::ty::maps::<impl rustc::ty::context::TyCtxt<'a, 'tcx, 'lcx>>::symbol_name
   19: <rustc_trans::base::ValueIter as core::iter::iterator::Iterator>::next
   20: <rustc_trans::ModuleLlvm as core::fmt::Debug>::fmt
   21: <rustc_trans::base::ValueIter as core::iter::iterator::Iterator>::next
   22: rustc::dep_graph::graph::DepGraph::assert_ignored
   23: rustc::ty::maps::<impl rustc::ty::maps::queries::wasm_import_module_map<'tcx>>::try_get
   24: <rustc::ty::context::TyCtxt<'a, 'gcx, 'tcx> as rustc::ty::layout::HasTyCtxt<'gcx>>::tcx
   25: rustc::ty::maps::<impl rustc::ty::maps::queries::collect_and_partition_translation_items<'tcx>>::ensure
   26: rustc::ty::maps::<impl rustc::ty::maps::queries::collect_and_partition_translation_items<'tcx>>::try_get
   27: rustc::ty::maps::TyCtxtAt::collect_and_partition_translation_items
   28: rustc::ty::maps::<impl rustc::ty::context::TyCtxt<'a, 'tcx, 'lcx>>::collect_and_partition_translation_items
   29: <rustc_trans::LlvmTransCrate as rustc_trans_utils::trans_crate::TransCrate>::trans_crate
   30: rustc_driver::driver::build_output_filenames
   31: rustc_driver::driver::phase_4_translate_to_llvm
   32: <rustc_driver::pretty::UserIdentifiedItem as core::fmt::Debug>::fmt
   33: <rustc_driver::pretty::UserIdentifiedItem as core::fmt::Debug>::fmt
   34: <rustc_driver::pretty::UserIdentifiedItem as core::fmt::Debug>::fmt
   35: <rustc_driver::profile::trace::Query as core::fmt::Debug>::fmt
   36: rustc_driver::driver::compile_input
   37: rustc_driver::run_compiler
   38: rustc_driver::target_features::add_configuration
   39: <rustc_driver::derive_registrar::Finder as rustc::hir::itemlikevisit::ItemLikeVisitor<'v>>::visit_impl_item
   40: <rustc_driver::pretty::UserIdentifiedItem as core::fmt::Debug>::fmt
   41: _rust_maybe_catch_panic
   42: rustc_driver::driver::build_output_filenames
   43: <<std::sys_common::remutex::ReentrantMutex<T> as core::fmt::Debug>::fmt::LockedPlaceholder as core::fmt::Debug>::fmt
   44: std::sys::windows::thread::Thread::new
   45: BaseThreadInitThunk
   46: RtlSubscribeWnfStateChangeNotification
   47: RtlSubscribeWnfStateChangeNotification

and the relevant output of systeminfo:

Host Name:                 ---
OS Name:                   Microsoft Windows Server 2016 Datacenter
OS Version:                10.0.14393 N/A Build 14393
OS Manufacturer:           Microsoft Corporation
OS Configuration:          Standalone Server
OS Build Type:             Multiprocessor Free
Original Install Date:     9/8/2017, 2:59:51 PM
System Boot Time:          6/19/2018, 10:49:50 AM
System Manufacturer:       Xen
System Model:              HVM domU
System Type:               x64-based PC
Processor(s):              1 Processor(s) Installed.
                           [01]: Intel64 Family 6 Model 63 Stepping 2 GenuineIntel ~2400 Mhz
BIOS Version:              Xen 4.2.amazon, 8/24/2006
Windows Directory:         C:\Windows
System Directory:          C:\Windows\system32
Boot Device:               \Device\HarddiskVolume1
System Locale:             en-us;English (United States)
Input Locale:              en-us;English (United States)
Time Zone:                 (UTC-05:00) Eastern Time (US & Canada)
Total Physical Memory:     32,768 MB
Available Physical Memory: 30,423 MB
Virtual Memory: Max Size:  37,632 MB
Virtual Memory: Available: 35,042 MB
Virtual Memory: In Use:    2,590 MB

[ncoish]

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 (3eda71b 2018-06-19) running on i686-pc-windows-msvc

note: compiler flags: -C opt-level=3 --crate-type lib

[ncoish]

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]

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`.

[ncoish]

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]

@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]

@michaelwoerister Yes, it looks like the issue is this line in the self profiler:

rust/src/librustc/util/profiling.rs

Line 200 in 289ad6e

let elapsed = self.current_timer.elapsed();

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.

- https://doc.rust-lang.org/std/time/struct.Instant.html

[michaelwoerister]

@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]

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]

elapsed is just Instant::now() - *self, and instant subtraction panics on underflow. now on Windows is:

rust/src/libstd/sys/windows/time.rs

Lines 45 to 51 in 93fa2d7

	pub fn now() -> Instant {
	let mut t = Instant { t: 0 };
	cvt(unsafe {
	c::QueryPerformanceCounter(&mut t.t)
	}).unwrap();
	t
	}

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?