[Nothing to see here] Just borrowing Travis

[scottmcm]

Write start and finish times from bootstrap rustc

[rust-highfive]

r? @nikomatsakis

(rust_highfive has picked a reviewer for you, use r? to override)

[kennytm]

The log looks really strange.

The Compiling unwind v0.0.0 (file:///checkout/src/libunwind) line appears at [00:04:02], however the corresponding BOOTSTRAP_TIMING start appears at [00:04:34].

Seems like the BOOTSTRAP_TIMING reflects the true dependency ordering of the crates, while the Compiling messages just shows when they are scheduled, not when rustc is actually invoked.

[00:04:02]    Compiling cc v1.0.4
[00:04:02]    Compiling cfg-if v0.1.2
[00:04:02]    Compiling libc v0.2.36
[00:04:02]    Compiling unwind v0.0.0 (file:///checkout/src/libunwind)
[00:04:02]    Compiling core v0.0.0 (file:///checkout/src/libcore)
[00:04:02] (BOOTSTRAP_TIMING start stage0 core at Duration { secs: 1520584212, nanos: 463352446 })
[00:04:03]    Compiling filetime v0.1.15
[00:04:05]    Compiling build_helper v0.1.0 (file:///checkout/src/build_helper)
[00:04:08]    Compiling std v0.0.0 (file:///checkout/src/libstd)
[00:04:09]    Compiling alloc_jemalloc v0.0.0 (file:///checkout/src/liballoc_jemalloc)
[00:04:09]    Compiling compiler_builtins v0.0.0 (file:///checkout/src/rustc/compiler_builtins_shim)
[00:04:11]    Compiling cmake v0.1.29
[00:04:16]    Compiling rustc_tsan v0.0.0 (file:///checkout/src/librustc_tsan)
[00:04:18]    Compiling rustc_msan v0.0.0 (file:///checkout/src/librustc_msan)
[00:04:20]    Compiling rustc_asan v0.0.0 (file:///checkout/src/librustc_asan)
[00:04:21]    Compiling rustc_lsan v0.0.0 (file:///checkout/src/librustc_lsan)
[00:04:32] (BOOTSTRAP_TIMING finish stage0 core at Duration { secs: 1520584242, nanos: 329527980 })
[00:04:32]    Compiling libc v0.0.0 (file:///checkout/src/rustc/libc_shim)
[00:04:32]    Compiling std_unicode v0.0.0 (file:///checkout/src/libstd_unicode)
[00:04:32] (BOOTSTRAP_TIMING start stage0 libc at Duration { secs: 1520584242, nanos: 334506946 })
[00:04:32] (BOOTSTRAP_TIMING start stage0 compiler_builtins at Duration { secs: 1520584242, nanos: 338799595 })
[00:04:32] (BOOTSTRAP_TIMING start stage0 std_unicode at Duration { secs: 1520584242, nanos: 340267037 })
[00:04:34] (BOOTSTRAP_TIMING finish stage0 libc at Duration { secs: 1520584243, nanos: 771551334 })
[00:04:34]    Compiling panic_abort v0.0.0 (file:///checkout/src/libpanic_abort)
[00:04:34] (BOOTSTRAP_TIMING start stage0 unwind at Duration { secs: 1520584243, nanos: 785774368 })
[00:04:34] (BOOTSTRAP_TIMING start stage0 panic_abort at Duration { secs: 1520584243, nanos: 788074019 })
[00:04:34] (BOOTSTRAP_TIMING finish stage0 panic_abort at Duration { secs: 1520584244, nanos: 44258586 })
[00:04:34] (BOOTSTRAP_TIMING finish stage0 unwind at Duration { secs: 1520584244, nanos: 87448991 })
[00:04:34] (BOOTSTRAP_TIMING finish stage0 std_unicode at Duration { secs: 1520584244, nanos: 234464788 })
[00:04:34]    Compiling alloc v0.0.0 (file:///checkout/src/liballoc)
[00:04:34] (BOOTSTRAP_TIMING start stage0 alloc at Duration { secs: 1520584244, nanos: 239537365 })
[00:04:35] (BOOTSTRAP_TIMING finish stage0 compiler_builtins at Duration { secs: 1520584244, nanos: 832204394 })
[00:04:41] (BOOTSTRAP_TIMING finish stage0 alloc at Duration { secs: 1520584250, nanos: 764584990 })
[00:04:41]    Compiling alloc_system v0.0.0 (file:///checkout/src/liballoc_system)
[00:04:41]    Compiling panic_unwind v0.0.0 (file:///checkout/src/libpanic_unwind)
[00:04:41] (BOOTSTRAP_TIMING start stage0 alloc_system at Duration { secs: 1520584250, nanos: 769126991 })
[00:04:41] (BOOTSTRAP_TIMING start stage0 panic_unwind at Duration { secs: 1520584250, nanos: 772813874 })
[00:04:41] (BOOTSTRAP_TIMING finish stage0 alloc_system at Duration { secs: 1520584251, nanos: 36146612 })
[00:04:41] (BOOTSTRAP_TIMING start stage0 rustc_asan at Duration { secs: 1520584251, nanos: 45239009 })
[00:04:41] (BOOTSTRAP_TIMING start stage0 rustc_tsan at Duration { secs: 1520584251, nanos: 47368399 })
[00:04:41] (BOOTSTRAP_TIMING start stage0 alloc_jemalloc at Duration { secs: 1520584251, nanos: 54204046 })
[00:04:41] (BOOTSTRAP_TIMING finish stage0 panic_unwind at Duration { secs: 1520584251, nanos: 273406256 })
[00:04:41] (BOOTSTRAP_TIMING start stage0 rustc_msan at Duration { secs: 1520584251, nanos: 280254322 })
[00:04:41] (BOOTSTRAP_TIMING finish stage0 rustc_asan at Duration { secs: 1520584251, nanos: 384129057 })
[00:04:41] (BOOTSTRAP_TIMING start stage0 rustc_lsan at Duration { secs: 1520584251, nanos: 391278812 })
[00:04:41] (BOOTSTRAP_TIMING finish stage0 rustc_tsan at Duration { secs: 1520584251, nanos: 397935866 })
[00:04:41] (BOOTSTRAP_TIMING finish stage0 alloc_jemalloc at Duration { secs: 1520584251, nanos: 408354750 })
[00:04:41] (BOOTSTRAP_TIMING finish stage0 rustc_msan at Duration { secs: 1520584251, nanos: 584493903 })
[00:04:41] (BOOTSTRAP_TIMING finish stage0 rustc_lsan at Duration { secs: 1520584251, nanos: 655721123 })
[00:04:41] (BOOTSTRAP_TIMING start stage0 std at Duration { secs: 1520584251, nanos: 660358427 })
[00:05:04] (BOOTSTRAP_TIMING finish stage0 std at Duration { secs: 1520584274, nanos: 483550347 })
[00:05:04]     Finished release [optimized] target(s) in 62.18 secs

[scottmcm]

@kennytm Yeah, I've always found the Compiling messages confusing. I guess they're pre-order, rather than in-order? It's most obvious to me with things like rustc_driver, which is "Compiling" at [00:06:32], but obviously can't do anything until all the parts of the compiler it needs to call get compiled, so doesn't actually start until [00:24:58].

As an aside, is this the correct way to get an environment variable?
https://github.com/rust-lang/rust/pull/48867/files#diff-354f30a63fb0907d4ad57269548329e3R15
I tried that the first time, but this check (which might also be wrong, but worked locally) didn't get it in travis, so I ended up commenting it out.
https://github.com/rust-lang/rust/pull/48867/files#diff-f9ca680965b2b478a96d943da34e0c71R289

(Closing since I have the log I wanted from this.)