Tracking issue on Reducing bors cycle time

[kennytm]

Problems

• Spurious timeout in the asmjs builder rust#48826 (Spurious timeout in the asmjs builder)
• Spurious timeout in dist builders rust#48827 (Spurious timeout in dist builders)

Investigations

• Collect CPU utilization statistics of CI builders rust#48828 (Collect CPU utilization statistics of CI builders)
• Collect and aggregate timing statistics of CI builders rust#48829 (Collect and aggregate timing statistics of CI builders)
• Keep balancing "split" AppVeyor jobs rust#48844 (Keep balancing "split" AppVeyor jobs)

[kennytm]

A minor update.

Since we have split the AppVeyor jobs and upgraded AppVeyor to use quad-core, Travis becomes the slowest builder nowadays. The most recent build #75709 caught my attention as it spent 2 hr 43 min to complete, whereas typical build time (e.g. the previous build #75703) is around 2 hr 10 min.

The slowest job is i686-gnu. If we breakdown the time spent and compare the two builds, we see the typical "everything just became slower" behavior.

(time spent in minutes)	#75709	#75703
stage1-rustc	38	27
stage0-rustc	24	18
test/run-pass	12	9
test/run-pass-fulldeps	9	7
test-stage2-libcore	6	5
llvm	5	5
rustdoc	5	4
test-stage2-libstd	5	4
stage2-rustbook	5	3
test-stage2-liballoc	3	2
stage0-compiletest	3	2
test/run-make-fulldeps	3	2

From the cpuinfo we do see 75709 is scheduled on a slower CPU:

• #75709: Intel(R) Xeon(R) CPU @ 2.50GHz (model 62 stepping 4 = E5-2609) × 4
• #75703: Intel(R) Xeon(R) CPU @ 2.60GHz (model 45 stepping 7 = E5-2670) × 4

https://ark.intel.com/compare/64595,64588

Since we cannot "choose" which CPU the jobs are scheduled on I guess there's nothing we could do 🙃. Though 2.6 / 2.5 = 1.04 seems insufficient to explain the 25% slowdown.

The build time of each crate of the stage1-rustc step is:

crate	minutes
rustc	15
rustc_mir	10
rustc_typeck	8
rustc_metadata	7
rustc_incremental	3
syntax	3
rustc_resolve	3
rustc_driver	2
rustc_allocator	2
rustc_save_analysis	2

The actual sum is 69 minutes, and the elapsed time for stage1-rustc is 38 minutes. If rustbuild is really using 1 CGU (not sure what happened after rust-lang/rust#48892), this means with cargo's parallelism we are just barely using 2 cores on this 4-core machine, and it is not nice. We may want to check whether rustc is blocking the entire dependency graph and why and what to do.

Most of these problems are probably quite well-known.

[alexcrichton]

@kennytm oh FWIW we should be using 16 CGUs by default on all release builders currently, but if we aren't that may be a bug!

[kennytm]

@alexcrichton Ah I see, though i686-gnu is a test builder.

Perhaps we should redo rust-lang/rust#48828 some day since using 16 CGU may have changed the analysis result.

[alexcrichton]

Indeed yeah! I'd prefer to have actual confirmation that we're saturating what we think we are...