Nightly rust hangs forever

[zonyitoo]

When I tried to use nightly rust to compile my project shadowsocks-rust, it will hang forever.

Stable version works fine.

Reproduce steps:

$ git clone https://github.com/shadowsocks/shadowsocks-rust.git
$ cd shadowsocks-rust
$ cargo install -f
  Installing shadowsocks-rust v1.6.10-nightly (file:///Users/zonyitoo/Projects/shadowsocks-rust)
 Downloading openssl v0.9.22
 Downloading serde v1.0.23
 Downloading num-traits v0.1.41
 Downloading openssl-sys v0.9.22
 Downloading foreign-types v0.3.2
 Downloading foreign-types-shared v0.1.1
    Blocking waiting for file lock on memchr-2.0.1.crate
   Compiling typenum v1.9.0
   Compiling unicode-width v0.1.4
   Compiling openssl v0.9.22
   Compiling lazycell v0.5.1
   Compiling strsim v0.6.0
   Compiling num-traits v0.1.41
... (many more logs)
   Compiling env_logger v0.4.3
   Compiling shadowsocks-rust v1.6.10-nightly (file:///Users/zonyitoo/Projects/shadowsocks-rust)

It will hang forever, but still consumes CPU.

ps shows a rustc process:

zonyitoo         14287  98.3  0.0 25306648   1012 s001  R+   10:36下午  17:20.50 /Users/zonyitoo/.rustup/toolchains/nightly-x86_64-apple-darwin/bin/rustc --crate-name shadowsocks src/lib.rs --crate-type lib --emit=dep-info,link -C opt-level=3 --cfg feature="default" --cfg feature="libsodium-ffi" --cfg feature="sodium" -C metadata=fb046a911106e95e -C extra-filename=-fb046a911106e95e --out-dir /Users/zonyitoo/Projects/shadowsocks-rust/target/release/deps -L dependency=/Users/zonyitoo/Projects/shadowsocks-rust/target/release/deps --extern serde_urlencoded=/Users/zonyitoo/Projects/shadowsocks-rust/target/release/deps/libserde_urlencoded-61a60925e70dcbe4.rlib --extern lazy_static=/Users/zonyitoo/Projects/shadowsocks-rust/target/release/deps/liblazy_static-a066899e4d28630a.rlib --extern byteorder=/Users/zonyitoo/Projects/shadowsocks-rust/target/release/deps/libbyteorder-1cb3c8ca5707fac7.rlib --extern qrcode=/Users/zonyitoo/Projects/shadowsocks-rust/target/release/deps/libqrcode-c4d0865acf488074.rlib --extern tokio_signal=/Users/zonyitoo/Projects/shadowsocks-rust/target/release/deps/libtokio_signal-6fa3848f7558b050.rlib --extern url=/Users/zonyitoo/Projects/shadowsocks-rust/target/release/deps/liburl-42ffd8f1fd62548b.rlib --extern futures_cpupool=/Users/zonyitoo/Projects/shadowsocks-rust/target/release/deps/libfutures_cpupool-32ced888700d9e3b.rlib --extern scoped_tls=/Users/zonyitoo/Projects/shadowsocks-rust/target/release/deps/libscoped_tls-50ac73adf01c31a4.rlib --extern serde_json=/Users/zonyitoo/Projects/shadowsocks-rust/target/release/deps/libserde_json-cc1e76046d610c86.rlib --extern openssl=/Users/zonyitoo/Projects/shadowsocks-rust/target/release/deps/libopenssl-91c6f1f26b8759c6.rlib --extern subprocess=/Users/zonyitoo/Projects/shadowsocks-rust/target/release/deps/libsubprocess-0a3efa9a446563ca.rlib --extern digest=/Users/zonyitoo/Projects/shadowsocks-rust/target/release/deps/libdigest-c6d1d61fc5bc9bf0.rlib --extern libsodium_ffi=/Users/zonyitoo/Projects/shadowsocks-rust/target/release/deps/liblibsodium_ffi-f0ea0ac518324990.rlib --extern bytes=/Users/zonyitoo/Projects/shadowsocks-rust/target/release/deps/libbytes-54eacfdfc8e87665.rlib --extern ring=/Users/zonyitoo/Projects/shadowsocks-rust/target/release/deps/libring-6add70aa26956a4c.rlib --extern typenum=/Users/zonyitoo/Projects/shadowsocks-rust/target/release/deps/libtypenum-fdfe19e18f298fbb.rlib --extern time=/Users/zonyitoo/Projects/shadowsocks-rust/target/release/deps/libtime-37bf8783b022cc7e.rlib --extern md_5=/Users/zonyitoo/Projects/shadowsocks-rust/target/release/deps/libmd_5-f51cf7bee16cb806.rlib --extern libc=/Users/zonyitoo/Projects/shadowsocks-rust/target/release/deps/liblibc-8e42d4cf8815835d.rlib --extern clap=/Users/zonyitoo/Projects/shadowsocks-rust/target/release/deps/libclap-2f9d9629604ac78b.rlib --extern env_logger=/Users/zonyitoo/Projects/shadowsocks-rust/target/release/deps/libenv_logger-37a09170e3cd67b7.rlib --extern futures=/Users/zonyitoo/Projects/shadowsocks-rust/target/release/deps/libfutures-7614b080b7aa6bfa.rlib --extern byte_string=/Users/zonyitoo/Projects/shadowsocks-rust/target/release/deps/libbyte_string-8e53eb4422822c2d.rlib --extern rand=/Users/zonyitoo/Projects/shadowsocks-rust/target/release/deps/librand-ba32c60615891fa3.rlib --extern tokio_io=/Users/zonyitoo/Projects/shadowsocks-rust/target/release/deps/libtokio_io-0ba48e8839c90dec.rlib --extern log=/Users/zonyitoo/Projects/shadowsocks-rust/target/release/deps/liblog-db3a3cc0c4299968.rlib --extern base64=/Users/zonyitoo/Projects/shadowsocks-rust/target/release/deps/libbase64-519a09b2f17b9fbf.rlib --extern tokio_core=/Users/zonyitoo/Projects/shadowsocks-rust/target/release/deps/libtokio_core-c3e74c59a01ac9ad.rlib -L native=/usr/local/Cellar/libsodium/1.0.15/lib -L native=/usr/local/opt/openssl@1.1/lib -L native=/Users/zonyitoo/Projects/shadowsocks-rust/target/release/build/ring-c441a9fe61114cc0/out

Meta

• rustc:

rustc 1.24.0-nightly (23032d0af 2017-11-30)
binary: rustc
commit-hash: 23032d0afa2b0e0c60a9b2ae62709f846d90007c
commit-date: 2017-11-30
host: x86_64-apple-darwin
release: 1.24.0-nightly
LLVM version: 4.0

• cargo: cargo 0.24.0-nightly (6529d418d 2017-11-29)

Is that a git bisect result for the commit id or something else, it's a little unclear from the comments here. If not then I would recommend running git bisect on the nightly build that's failing and report it back. After that me and others can figure out if reverted is possible or works cleanly. If not then a fix should be applied based on what git bisect returns.

[zonyitoo]

I found this problem after rustup update. So I don't remember which exact commit I was on before update.

It would be the last version before Nov. 1. I guess.

Actually you can run git bisect on the git repo here: https://github.com/rust-lang/rust/commits/master. As it's up to date. Just clone it and build it. Actually you don't need commit ids, that makes it run faster a few less bisections. If you run git bisect bad or good without commit for both, it runs it against the complete history rather than a range of commits.

[Mark-Simulacrum]

Last few lines of SODIUM_BUILD_STATIC=yes cargo rustc --lib --release -- --emit=llvm-ir -Ztime-passes -Ztime-llvm-passes -Zprint-llvm-passes are below. It might be due to ThinLTO being enabled by default perhaps (purely based on -write-thinlto-bitcode? cc @alexcrichton

@xerofoify Generally running git bisect isn't too useful in most cases due to how slow that'll be. It's probably easier to bisect using the CI artifacts, which I'll attempt to do myself soon. We try to diagnose the problem ourselves before asking reporters to do so since it's likely our bug.

    time: 0.055; rss: 193MB     write metadata
    time: 3.273; rss: 224MB     translation item collection
    time: 0.017; rss: 232MB     codegen unit partitioning
    time: 4.273; rss: 326MB     translate to LLVM IR
    time: 0.000; rss: 326MB     assert dep graph
    time: 0.000; rss: 326MB     serialize dep graph
  time: 7.792; rss: 326MB       translation
    time: 0.772; rss: 284MB     llvm function passes [shadowsocks0]
    time: 90.584; rss: 6616MB   llvm module passes [shadowsocks0]
Pass Arguments:  -profile-summary-info -module-summary-analysis -write-thinlto-bitcode
Profile summary info
  ModulePass Manager
    Module Summary Analysis
      Unnamed pass: implement Pass::getPassName()
    ThinLTO Bitcode Writer
Pass Arguments:  -domtree -loops -branch-prob -block-freq
  FunctionPass Manager
    Dominator Tree Construction
    Natural Loop Information
    Branch Probability Analysis
    Block Frequency Analysis

Sorry about that, wasn't sure what the protocol for git bisect was here :).

[Mark-Simulacrum]

Looks like this was caused by #45225 (cc @eddyb). I suspect that LLVM is struggling with the IR we're handing it...

[eddyb]

@Mark-Simulacrum I don't understand the log, is LLVM just slower, or does it end up in some loop?
I feel like we've seen one such bug before but I can't remember which one it was.

[Mark-Simulacrum]

It's possible it's just slower, I didn't try looking at what was happening with gdb or anything. The memory usage did seem to keep growing so it presumably as doing something....

It will hang forever, but still consums CPU.

ps shows a rustc process:

zonyitoo 14287 98.3 0.0 25306648 1012 s001 R+ 10:36下午 17:20.50 /Users/zonyitoo/.rustup/toolchains/nightly-x86_64-apple-darwin/bin/rustc --crate-name shadowsocks

Is what the log states. We should check if the build for rust supports it this occurs under gcc as it if does then we have a issue with us and the compiler.

I am curious what is meant by this through:
avoiding LLVM's "first-class aggregates"

in this commit, #45225?

[kennytm]

The error only happens when optimization level ≥2. Number of CGUs (ThinLTO) is irrelevant. Most time is spent on SROALegacyPass

[kennytm]

I've enabled some debug log for the SROA pass and looks like there's difficulty working with futures::future::AndThen::poll. SROA-ing every such call takes nearly 2 minutes, and there are at least 28 futures-related and_thens in the shadowsocks-rust package…

[00:00:00]    Compiling shadowsocks-rust v1.6.10 (file://$DIR/shadowsocks-rust)
[00:00:00]      Running `rustc --crate-name shadowsocks src/lib.rs --crate-type lib --emit=dep-info,link -C opt-level=3 --cfg 'feature="default"' --cfg 'feature="libsodium-ffi"' --cfg 'feature="sodium"' -C metadata=875e43cd17c0b5a0 -C extra-filename=-875e43cd17c0b5a0 --out-dir $DIR/shadowsocks-rust/target/release/deps -L dependency=$DIR/shadowsocks-rust/target/release/deps --extern tokio_signal=$DIR/shadowsocks-rust/target/release/deps/libtokio_signal-d8d02ef07068b1ca.rlib --extern subprocess=$DIR/shadowsocks-rust/target/release/deps/libsubprocess-3c1ecbd141d33dff.rlib --extern openssl=$DIR/shadowsocks-rust/target/release/deps/libopenssl-1b60528d713e083d.rlib --extern bytes=$DIR/shadowsocks-rust/target/release/deps/libbytes-7b105104e2fe57f0.rlib --extern md_5=$DIR/shadowsocks-rust/target/release/deps/libmd_5-f4490bb4d711237a.rlib --extern lazy_static=$DIR/shadowsocks-rust/target/release/deps/liblazy_static-dd36e56c4b5b6e36.rlib --extern tokio_core=$DIR/shadowsocks-rust/target/release/deps/libtokio_core-cd674c1cee8f4b35.rlib --extern scoped_tls=$DIR/shadowsocks-rust/target/release/deps/libscoped_tls-2741372f6d09b8f2.rlib --extern ring=$DIR/shadowsocks-rust/target/release/deps/libring-28456fadef0887d9.rlib --extern libsodium_ffi=$DIR/shadowsocks-rust/target/release/deps/liblibsodium_ffi-3c35aa1af33659fd.rlib --extern libc=$DIR/shadowsocks-rust/target/release/deps/liblibc-187fc6c13f99925e.rlib --extern byte_string=$DIR/shadowsocks-rust/target/release/deps/libbyte_string-f2e9086bfb1da425.rlib --extern qrcode=$DIR/shadowsocks-rust/target/release/deps/libqrcode-8986450b39a075af.rlib --extern url=$DIR/shadowsocks-rust/target/release/deps/liburl-4b2c5f911212381c.rlib --extern serde_urlencoded=$DIR/shadowsocks-rust/target/release/deps/libserde_urlencoded-25effef210302280.rlib --extern serde_json=$DIR/shadowsocks-rust/target/release/deps/libserde_json-09584eb04dca168e.rlib --extern digest=$DIR/shadowsocks-rust/target/release/deps/libdigest-faeede511d72a534.rlib --extern typenum=$DIR/shadowsocks-rust/target/release/deps/libtypenum-0ea64efc715818d9.rlib --extern time=$DIR/shadowsocks-rust/target/release/deps/libtime-9a37c4925e6970b3.rlib --extern clap=$DIR/shadowsocks-rust/target/release/deps/libclap-a8b942b4941c7197.rlib --extern env_logger=$DIR/shadowsocks-rust/target/release/deps/libenv_logger-3c47b9db34b73bb5.rlib --extern byteorder=$DIR/shadowsocks-rust/target/release/deps/libbyteorder-390f9f29da931bec.rlib --extern tokio_io=$DIR/shadowsocks-rust/target/release/deps/libtokio_io-14bba7a8919ac847.rlib --extern futures=$DIR/shadowsocks-rust/target/release/deps/libfutures-5b90b645077d9497.rlib --extern log=$DIR/shadowsocks-rust/target/release/deps/liblog-820009db7805861d.rlib --extern base64=$DIR/shadowsocks-rust/target/release/deps/libbase64-e45e06e9dc086d37.rlib --extern futures_cpupool=$DIR/shadowsocks-rust/target/release/deps/libfutures_cpupool-bb8344cc22845bf3.rlib --extern rand=$DIR/shadowsocks-rust/target/release/deps/librand-0b5438783367eeba.rlib -L native=/usr/local/Cellar/libsodium/1.0.15/lib -L native=/usr/local/opt/openssl/lib -L native=$DIR/shadowsocks-rust/target/release/build/ring-b4c40f80f2d65dd1/out`
[00:00:50] SROA function: _ZN100_$LT$$RF$$u27$a$u20$mut$u20$alloc..vec..Vec$LT$T$GT$$u20$as$u20$core..iter..traits..IntoIterator$GT$9into_iter17h29e23af86a7d2c85E
...
<skipped 17832 lines>
...
[00:01:10] SROA function: _ZN65_$LT$futures..future..chain..Chain$LT$A$C$$u20$B$C$$u20$C$GT$$GT$4poll17h05ca77dd1cc1739aE
[00:01:10] Promoting allocas with mem2reg...
[00:01:10] SROA function: _ZN105_$LT$futures..future..and_then..AndThen$LT$A$C$$u20$B$C$$u20$F$GT$$u20$as$u20$futures..future..Future$GT$4poll17hca25b69dd59146a1E
[00:02:30] Promoting allocas with mem2reg...
[00:03:02] SROA function: _ZN4core3mem7size_of17h9931e69b61525598E
[00:03:02] SROA function: _ZN4core3ptr19swap_nonoverlapping17h48ec9f255a445c1bE
[00:03:02] SROA function: _ZN4core3mem4swap17h58bbc82a017d5836E
...
<skipped 86 lines>
...
[00:03:03] SROA function: _ZN65_$LT$futures..future..chain..Chain$LT$A$C$$u20$B$C$$u20$C$GT$$GT$4poll17h6788e14405a2ffadE
[00:03:03] Promoting allocas with mem2reg...
[00:03:03] SROA function: _ZN105_$LT$futures..future..and_then..AndThen$LT$A$C$$u20$B$C$$u20$F$GT$$u20$as$u20$futures..future..Future$GT$4poll17h466afb4be6fc7f15E
[00:04:16] Promoting allocas with mem2reg...
[00:04:59] SROA function: _ZN4core3mem7size_of17he136b9e66cd6b59bE
[00:04:59] SROA function: _ZN4core3ptr19swap_nonoverlapping17hdeab54ab4295f4f6E
[00:04:59] SROA function: _ZN4core3mem4swap17h82cdf9db11f129e6E
...

Ok at least from my knowledge this is possibly a issue with LLVM in optimizations if it's failing like that. What version of LLVM is being used here. Maybe a newer version fixes it from upstream already?