AppVeyor's 32-bit MSVC testing become extremely slow since August 13th

[kennytm]

The time to complete the i686-pc-windows-msvc build has became dangerously close to 3 hours starting from August 13th.

Assuming AppVeyor is normal, I suspect one or more of the following are responsible:

• Build 4266 (Expose all OS-specific modules in libstd doc. #43348 "Expose all OS-specific modules in libstd doc.") (1 hr 50 min → 2 hr 3 min = +13 min)
• Build 4267 (Rustbuild cleanups/fixes and improvements #43630 "Rustbuild cleanups/fixes and improvements") (2 hr 3 min → 2 hr 25 min = +22 min)
• Build 4269 (Rollup of 8 pull requests #43839 "Rollup of 8 pull requests") (2 hr 25 min → 2 hr 33 min = +8 min)
• Build 4274 (Optimize allocation paths in RawVec #43815 "Optimize allocation paths in RawVec") (2 hr 33 min → 2 hr 50 min = +17 min)

I'll check the detailed timing breakdown later.

Raw timing data from AppVeyor

AppVeyor build	check-64-msvc	check-32-msvc	check-aux	check-32-gnu	check-64-gnu	dist-64-msvc	dist-32-msvc	dist-32-gnu	dist-64-gnu	dist-alt
4251	1.82	2.23	1.95	2.17	1.77	1.45	1.62	1.53	1.48	1.2
4252	1.82	1.95	1.65	1.9	1.67	1.45	1.72	1.48	1.55	1.18
4253	1.78	1.93	1.9	1.88	1.65	1.45	1.5	1.45	1.48	1.25
4254	1.75	1.9	1.53	2.12	1.75	1.35	1.58	1.38	1.28	1.15
4255	1.9	2.13	1.75	1.87	1.55	1.47	1.58	1.58	1.33	1.12
4257	1.7	2.17	1.8	1.83	1.6	1.25	1.52	1.38	1.33	1.25
4258	1.6	2.03	1.7	1.73	1.52	1.48	1.68	1.35	1.37	1.1
4259	1.67	1.95	1.82	1.83	1.62	1.47	1.73	1.38	1.38	1.15
4260	1.62	2.25	1.68	1.93	1.8	1.47	1.52	1.37	1.62	1.18
4262	1.67	2.43	1.57	1.78	1.63	1.68	1.62	1.87	1.37	1.2
4263	1.8	1.83	1.7	1.85	1.65	1.77	1.7	1.28	1.8	1.17
4266	2.22	2.05	1.6	1.68	2.15	1.28	1.8	1.9	1.37	1.15
4267	1.58	2.42	1.65	1.72	1.6	1.32	1.48	1.35	1.23	1.15
4268	1.48	2.52	1.6	1.88	1.48	1.82	1.47	1.33	1.25	1.13
4269	2.3	2.55	1.73	2.17	1.75	1.2	1.48	1.38	1.3	1.28
4274	1.82	2.83	1.85	1.9	1.62	1.28	1.67	1.45	1.42	1.18
4276	1.82	2.62	1.72	2.05	1.73	1.42	1.63	1.48	1.5	1.2
4277	1.65	2.88	1.78	1.98	1.55	1.27	1.63	1.42	1.43	1.08
4278	1.82	2.73	1.72	2.03	1.57	1.25	1.55	1.4	1.4	1.17
4279	1.75	2.92	1.72	1.93	1.77	1.42	1.55	1.48	1.38	1.25
4283	1.88	2.82	1.8	1.95	1.82	1.38	1.73	1.5	1.48	1.3
4284	1.75	2.82	1.82	2.15	1.8	1.4	1.73	1.52	1.47	1.32
4285	1.87	2.8	1.82	1.93	1.67	1.38	1.67	1.52	1.58	1.32
4286	1.68	2.97	1.82	1.93	1.65	1.42	1.55	1.48	1.42	1.23
4287	1.73	2.73	1.7	1.85	1.72	1.43	1.58	1.57	1.37	1.15
4289	1.68	2.9	1.85	1.87	1.77	1.42	1.55	1.55	1.55	1.15
4290	1.68	2.7	1.83	2.05	1.75	1.35	1.57	1.57	1.42	1.17

The raw data is extracted by running

$('[ng-controller="ProjectBuildJobsController"] .project-build-state').map(function() { return this.innerText.replace(/(\d+) hr (\d+) min/g, (_, h, m) => (+h + m/60).toFixed(2)) }).toArray().join('\n')

in the browser's console.

[kennytm]

The cause is definitely #43630 (cc @Mark-Simulacrum), but arguably #43630 is doing the right thing.

There are two noticeable change with build 4267:

• The non-full-deps test cases are all run twice, once for i686 and once for i586. This is because the job is configured as --build=i686-pc-windows-msvc --target=i586-pc-windows-msvc, and Rustbuild cleanups/fixes and improvements #43630 now respects --target. These tests occpied 43 minutes in build 4267.
• The error_index_generator takes a much longer time to build (6 seconds → 2 minutes).

The other builds become slower probably only because AppVeyor was busier at that time.

While this is correct to test both i586 and i686, this pushes the complete test time too close to 3 hours. If AppVeyor become really slow, the build will spuriously timeout and 3 hours are wasted.

Is it a good idea to not test i586-pc-windows-msvc (since it is Tier 2)?

Detailed timing breakdown

Step \ AppVeyor Build	4263	4266	4267	4268	4269	4274	4276
make prepare	50.45	57.44	48.41	49.62	50.22	55.6	50.41
stage0-std	41.97	49.7	40.16	43.2	40.77	44.31	41.99
stage0-tidy	7.77	8.55	7.39	7.46	7.36	8.7	7.8
bootstrap	24.29	29.83	24.18	25.95	24.68	26.47	24.9
stage0-test	13.79	17.16	14.33	16.12	14.52	16.33	15.31
LLVM	365.957	424.254	361.585	375.589	378.536	404.563	373
stage0-rustc	806.91	868.14	749.73	804.31	783.56	852.76	805.1
stage1-std	52.9	62.55	50.71	57.55	52.56	57.63	56.44
stage1-test	21.24	23.9	19.97	21.86	20.5	24.1	22.28
stage1-rustc	1158.53	1296.72	1077.63	1144.87	1149.6	1252.53	1216.93
stage0-compiletest	27.28	32.71	28.62	28.87	29.51	29.37	31.28
*ui	27.423	31.642	26.342	26.892	26.597	30.841	28.297
*run-pass	1013.19	1187.58	1009.99	1016.6	1046.44	1166.81	1044.2
*compile-fail	287.183	355.433	304.579	308.519	310.566	347.332	302.841
*parse-fail	4.954	5.604	5.194	5.266	5.497	5.907	5.329
*run-fail	26.864	28.696	26.133	27.687	27.229	29.963	27.75
*run-pass-valgrind	3.444	3.537	3.329	3.379	3.44	3.746	3.578
*mir-opt	8.948	9.397	9.08	8.784	9.392	9.76	8.996
*codegen	5.832	6.369	5.727	6.074	5.817	6.868	6.008
*codegen-units	6.593	7.038	6.51	6.685	6.703	7.407	6.542
*incremental	49.843	54.778	47.788	48.976	49.579	54.414	51.378
stage2-std			52.3	53.41	52.91	60.25	56.41
stage2-test			19.62	21.13	21.12	24.4	22.2
*ui (i586)			26.299	28.493	29.035	31.089	28.815
*run-pass (i586)			1437.81	1505.96	1553	1751.56	1577.3
*compile-fail (i586)			470.995	499.857	503.985	594.714	535.056
*parse-fail (i586)			5.015	6.204	6.302	6.421	6.208
*run-fail (i586)			26.864	28.066	27.981	31.16	28.569
*run-pass-valgrind (i586)			3.272	3.505	3.484	3.765	3.456
*mir-opt (i586)			8.5	9.332	8.277	9.331	8.942
*codegen (i586)			5.536	5.676	5.622	6.727	6.114
*codegen-units (i586)			6.632	6.452	6.324	7.464	6.65
*incremental (i586)			48.511	50.859	50.5	56.687	51.932
*ui-fulldeps	11.762	12.581	13.103	11.989	12.118	14.966	14.565
*run-pass-fulldeps	173.33	194.091	162.713	165.575	175.214	200.576	184.015
*run-fail-fulldeps	3.26	3.609	2.963	3.072	3.173	3.828	3.904
*compile-fail-fulldeps	55.994	64.093	53.362	54.819	57.621	68.376	62.979
stage1-rustdoc	163.52	207.62	171.72	180.3	178.41	208	186.82
*run-make	110.293	125.712	104.125	108.508	108.074	122.52	109.526
*rustdoc	68.669	80.836	64.422	71.027	69.292	81.654	71.899
stage0-rustdoc	116.78	138.56
stage1-std	208.17	234.76	207.68	206.94	209.8	244.55	221.94
*std	729.726	780.634	704.625	710.458	735.912	819.26	750.107
stage1-test	15.25	15.91	14.56	15.74	15.55	17.1	15.55
*test	16.301	16.916	15.589	21.145	20.067	23.242	19.882
stage2-std			204.14	219.5	226.4	245.58	220.88
*std (i586)			224.791	239.742	246.943	266.667	241.688
stage2-test			14.34	15.51	15.5	16.83	15.86
*test (i586)			14.884	16.26	16.193	22.958	20.805
stage1-rustc	346.26	360.29	330.62	341.4	353.83	380.42	362.82
*rustc	352.068	364.968	334.739	347.153	359.862	386.806	368.537
stage0-unstable-book-gen	10.76	10.19	10.38	12.5	11.69	11.48	11.95
stage0-rustbook	155.49	162.19	146.74	152.13	156.75	176.28	155.51
doc-std	20.3	17.49	15.28	15.64	16.57	17.75	16.11
doc-std (i586)			15.84	15.53	15.95	18.34	17.25
doc-proc_macro	3.12	2.26	2.55	2.5	2.24	3.98	2.85
stage0-error_index_generator	6.28	6.27	119.83	128.44	130.75	140.13	127.68
stage0-linkchecker	3.18	3.58	3	3.17	3.3	3.34	3.27
*doc test	229.692	245.528	217.33	224.115	231.72	245.141	233.086
*doc test error_index	64.195	69.459	61.078	65.39	67.182	72.287	65.15

[alexcrichton]

Thanks so much for the detailed investigation here @kennytm!

I... thought we were testing i586 all this time bug I guess not :(. I think we may have stopped testing awhile ago when we never detected a regression and wanted to get round 2 hours, so I think it's ok at the very least to go back to the status quo of not testing it.

All in all I think it's ok to not be testing it. Ideally we'd test everything but we just don't always have the capacity to do so :(

[kennytm]

Unfortunately the Macs and ARMs still take about 2.5 hours (not regression) 😞.