CI: spurious hang on x86_64-msvc-1 during rustc_macros compilation

[matthiaskrgr]

Sometimes the build hangs there.

Wed, 26 Jan 2022 05:45:45 GMT running 0 tests
Wed, 26 Jan 2022 05:45:45 GMT
Wed, 26 Jan 2022 05:45:45 GMT test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
Wed, 26 Jan 2022 05:45:45 GMT
Wed, 26 Jan 2022 05:45:45 GMT    Doc-tests rustc_log
Wed, 26 Jan 2022 05:45:45 GMT
Wed, 26 Jan 2022 05:45:45 GMT running 1 test
Wed, 26 Jan 2022 05:45:45 GMT test src\lib.rs - (line 15) ... ok
Wed, 26 Jan 2022 05:45:45 GMT
Wed, 26 Jan 2022 05:45:45 GMT test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.63s
Wed, 26 Jan 2022 05:45:45 GMT
Wed, 26 Jan 2022 05:45:45 GMT 	finished in 1.616 seconds
Wed, 26 Jan 2022 05:45:45 GMT [TIMING] Crate { compiler: Compiler { stage: 2, host: TargetSelection { triple: "x86_64-pc-windows-msvc", file: None } }, target: TargetSelection { triple: "x86_64-pc-windows-msvc", file: None }, mode: Rustc, test_kind: Test, krate: "rustc_log" } -- 1.618
Wed, 26 Jan 2022 05:45:45 GMT [TIMING] CrateLibrustc { compiler: Compiler { stage: 2, host: TargetSelection { triple: "x86_64-pc-windows-msvc", file: None } }, target: TargetSelection { triple: "x86_64-pc-windows-msvc", file: None }, test_kind: Test, krate: "rustc_log" } -- 0.000
Wed, 26 Jan 2022 05:45:45 GMT Set({"compiler\\rustc_macros"}) not skipped for "bootstrap::test::CrateLibrustc" -- not in ["src/test/ui", "src/tools/linkchecker"]
Wed, 26 Jan 2022 05:45:45 GMT Testing rustc_macros stage1 (x86_64-pc-windows-msvc -> x86_64-pc-windows-msvc)
Wed, 26 Jan 2022 05:45:46 GMT [RUSTC-TIMING] build_script_build test:false 0.695
Wed, 26 Jan 2022 05:45:46 GMT [RUSTC-TIMING] unicode_xid test:false 0.150
Wed, 26 Jan 2022 05:45:46 GMT [RUSTC-TIMING] build_script_build test:false 0.592
Wed, 26 Jan 2022 05:45:46 GMT [RUSTC-TIMING] proc_macro2 test:false 1.727
Wed, 26 Jan 2022 05:45:46 GMT [RUSTC-TIMING] quote test:false 0.726
Wed, 26 Jan 2022 05:45:46 GMT [RUSTC-TIMING] syn test:false 15.990
Wed, 26 Jan 2022 05:45:46 GMT [RUSTC-TIMING] synstructure test:false 1.921
Wed, 26 Jan 2022 05:45:46 GMT [RUSTC-TIMING] rustc_macros test:false 4.037
Wed, 26 Jan 2022 05:45:46 GMT    Compiling rustc_macros v0.1.0 (D:\a\rust\rust\compiler\rustc_macros)
Wed, 26 Jan 2022 09:11:12 GMT Error: The operation was canceled.

https://github.com/rust-lang-ci/rust/runs/4947161125?check_suite_focus=true#step:26:25990

[matthiaskrgr]

@rustbot modify labels: +T-infra +A-spurious +O-windows +O-windows-msvc

[ehuss]

One possibility could be something like #92829. That builder has assertions enabled.

[ehuss]

Also happening with i686-msvc-1, so not specific to x86_64.

#92740 (comment)

[ehuss]

The first occurrence that I can see started at 2022-01-04T11:17:14. Nothing in the previous 72 hours of PRs jumps out to me as a culprit.

2022-01-04T11:17:14 i686-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1653357520
2022-01-06T07:36:19 x86_64-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1662026346
2022-01-07T12:04:52 x86_64-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1667435439
2022-01-09T04:39:37 i686-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1673044124
2022-01-12T00:20:15 i686-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1685277640
2022-01-12T08:23:42 i686-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1686605232
2022-01-13T07:03:46 x86_64-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1691458824
2022-01-13T14:28:36 i686-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1693177296
2022-01-14T09:38:32 x86_64-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1697054432
2022-01-15T18:23:44 x86_64-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1702243285
2022-01-17T18:37:04 i686-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1709411238
2022-01-20T02:15:11 x86_64-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1721268924
2022-01-21T13:27:18 i686-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1728891690
2022-01-22T02:54:37 x86_64-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1731804538
2022-01-22T09:50:29 x86_64-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1732630782
2022-01-23T18:51:16 x86_64-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1736720953
2022-01-24T17:48:35 i686-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1741334808
2022-01-25T11:13:28 x86_64-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1745079474
2022-01-26T04:54:06 x86_64-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1749156693
2022-01-29T19:11:56 i686-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1766585471
2022-01-29T23:53:24 x86_64-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1767141352
2022-01-30T13:38:30 i686-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1768800982
2022-02-03T04:06:25 i686-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1787602538
2022-02-04T00:15:25 i686-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1792467077
2022-02-04T05:47:40 i686-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1793446405
2022-02-04T20:38:43 i686-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1797032901
2022-02-05T04:32:45 x86_64-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1798398892
2022-02-05T09:01:51 x86_64-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1798941458
2022-02-06T12:34:02 i686-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1802304244
2022-02-06T17:16:15 x86_64-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1802927941
2022-02-07T07:02:34 i686-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1805020799
2022-02-08T16:27:43 x86_64-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1813442789
2022-02-10T05:08:40 i686-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1822024216
2022-02-11T10:57:16 x86_64-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1828903505
2022-02-14T20:56:47 i686-msvc-1 https://github.com/rust-lang-ci/rust/actions/runs/1843439094

[ehuss]

It's been about 3 weeks since the last occurrence of this.

I wasn't able to reproduce this. I tried for several days to reproduce by running the two jobs over and over, but they never failed. I don't have any ideas why that it is.

My guess is that it might be sensitive to codegen layout, and some change has shuffled the code around enough to make it stop. Or maybe some PR incidentally fixed it?

My only other theory is that there is some kind of jobserver problem. Windows is the only platform driven by make, which could maybe introduce some oddity here.

Probably should keep an eye out for it in case it comes back. I won't do any more investigation. My experiments used the following change, which seemed to work when I tried an artificial hang. Might be worth considering adding something like this if the problem comes back.

diff --git a/src/bootstrap/bin/rustc.rs b/src/bootstrap/bin/rustc.rs
index 7105a2457e2..bdfce66c2d6 100644
--- a/src/bootstrap/bin/rustc.rs
+++ b/src/bootstrap/bin/rustc.rs
@@ -175,6 +175,19 @@ fn main() {
     let (child, status) = {
         let errmsg = format!("\nFailed to run:\n{:?}\n-------------", cmd);
         let mut child = cmd.spawn().expect(&errmsg);
+        let child_id = child.id().to_string();
+        std::thread::spawn(move || {
+            std::thread::sleep(std::time::Duration::from_secs(1000));
+            let status =
+                Command::new("C:\\Program Files (x86)\\Windows Kits\\10\\Debuggers\\x64\\cdb.exe")
+                    .args(["-c", "~*k;qd", "-p"])
+                    .arg(&child_id)
+                    .status()
+                    .unwrap();
+            if !status.success() {
+                eprintln!("cdb err?");
+            }
+        });
         let status = child.wait().expect(&errmsg);
         (child, status)
     };