Reduce flake in Fleet installer tests #6671

andrewlock · 2025-02-17T09:02:48Z

Summary of changes

Reduce the flake seen in Fleet installer tests

Reason for change

The fleet installer tests are currently very flaky. This is mostly due to the nightmare of trying to get the app to behave as it does elsewhere (which maybe we should just give up on, more on that later).

Implementation details

The simple details are:

Add a delay after running ServiceMonitor.exe before starting the app pool and sending the initial request
Add a hacky completed.txt file to allow tracking when the app has shutdown.

First, some history...

The design of the test app is that it starts, wait for itself to be ready to handle requests, sends a self-request, and then shuts down. This works great for Docker outside of IIS, because it means we know that we get exactly one request, once the app is ready, and the docker container exits once the sequence is complete. :chef-kiss:

On IIS, this just doesn't work. IIS does its best to make sure the app is always running. There's a bunch of other complexity. One of which is the only way to get the app running in the first place is to send a request to it, which messes with our snapshots (that's already handled). But a bigger issue is the shutdown - I just can't find a way to "wait" for it using the built-in behaviour. And without being able to wait for shutdown, we don't know exactly when the "expected" request has been sent.

So this has a hack - write to a file in the app when the app is shutting down. And spin in the powershell script, waiting for that file to exist.

Test coverage

I've run the tests repeatedly on this branch, and not seen any failures, so 🤞

Other details

Yeah, I know, the arbitrary delay could be a source of flake. I spent way too long trying to capture the output to explicitly wait for the expected output, but no matter what sort of redirection I tried, I couldn't capture it as I needed - it only writes to the redirected output when the process ends, and the process doesn't end 🙄 So yeah, this is a hack, but it works

andrewlock · 2025-02-17T09:37:35Z

Execution-Time Benchmarks Report ⏱️

Execution-time results for samples comparing the following branches/commits:

Execution-time benchmarks measure the whole time it takes to execute a program. And are intended to measure the one-off costs. Cases where the execution time results for the PR are worse than latest master results are shown in red. The following thresholds were used for comparing the execution times:

Welch test with statistical test for significance of 5%
Only results indicating a difference greater than 5% and 5 ms are considered.

Note that these results are based on a single point-in-time result for each branch. For full results, see the dashboard.

Graphs show the p99 interval based on the mean and StdDev of the test run, as well as the mean value of the run (shown as a diamond below the graph).

gantt
    title Execution time (ms) FakeDbCommand (.NET Framework 4.6.2) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6671) - mean (69ms)  : 66, 71
     .   : milestone, 69,
    master - mean (69ms)  : 66, 71
     .   : milestone, 69,

    section CallTarget+Inlining+NGEN
    This PR (6671) - mean (999ms)  : 975, 1023
     .   : milestone, 999,
    master - mean (996ms)  : 972, 1019
     .   : milestone, 996,

gantt
    title Execution time (ms) FakeDbCommand (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6671) - mean (102ms)  : 100, 104
     .   : milestone, 102,
    master - mean (101ms)  : 99, 103
     .   : milestone, 101,

    section CallTarget+Inlining+NGEN
    This PR (6671) - mean (675ms)  : 659, 692
     .   : milestone, 675,
    master - mean (675ms)  : 660, 691
     .   : milestone, 675,

gantt
    title Execution time (ms) FakeDbCommand (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6671) - mean (89ms)  : 87, 91
     .   : milestone, 89,
    master - mean (89ms)  : 87, 91
     .   : milestone, 89,

    section CallTarget+Inlining+NGEN
    This PR (6671) - mean (627ms)  : 613, 640
     .   : milestone, 627,
    master - mean (634ms)  : 614, 654
     .   : milestone, 634,

gantt
    title Execution time (ms) HttpMessageHandler (.NET Framework 4.6.2) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6671) - mean (191ms)  : 187, 196
     .   : milestone, 191,
    master - mean (191ms)  : 187, 195
     .   : milestone, 191,

    section CallTarget+Inlining+NGEN
    This PR (6671) - mean (1,109ms)  : 1086, 1133
     .   : milestone, 1109,
    master - mean (1,113ms)  : 1085, 1140
     .   : milestone, 1113,

gantt
    title Execution time (ms) HttpMessageHandler (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6671) - mean (271ms)  : 268, 275
     .   : milestone, 271,
    master - mean (271ms)  : 266, 276
     .   : milestone, 271,

    section CallTarget+Inlining+NGEN
    This PR (6671) - mean (862ms)  : 828, 895
     .   : milestone, 862,
    master - mean (868ms)  : 837, 898
     .   : milestone, 868,

gantt
    title Execution time (ms) HttpMessageHandler (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6671) - mean (263ms)  : 258, 268
     .   : milestone, 263,
    master - mean (262ms)  : 258, 267
     .   : milestone, 262,

    section CallTarget+Inlining+NGEN
    This PR (6671) - mean (838ms)  : 807, 870
     .   : milestone, 838,
    master - mean (848ms)  : 818, 878
     .   : milestone, 848,

andrewlock · 2025-02-17T10:44:32Z

Benchmarks Report for tracer 🐌

Benchmarks for #6671 compared to master:

1 benchmarks are faster, with geometric mean 1.139
1 benchmarks are slower, with geometric mean 1.130
All benchmarks have the same allocations

The following thresholds were used for comparing the benchmark speeds:

Mann–Whitney U test with statistical test for significance of 5%
Only results indicating a difference greater than 10% and 0.3 ns are considered.

Allocation changes below 0.5% are ignored.

Benchmark details

Benchmarks.Trace.ActivityBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Gen 2	Allocated
master	`StartStopWithChild`	net6.0	7.89μs	45ns	321ns	0.0148	0.00738	0	5.61 KB
master	`StartStopWithChild`	netcoreapp3.1	10.2μs	56ns	331ns	0.0244	0.00977	0	5.8 KB
master	`StartStopWithChild`	net472	16μs	61ns	236ns	1.04	0.299	0.102	6.22 KB
#6671	`StartStopWithChild`	net6.0	7.93μs	45ns	328ns	0.0113	0.00376	0	5.61 KB
#6671	`StartStopWithChild`	netcoreapp3.1	10.1μs	55.8ns	353ns	0.0187	0.00933	0	5.81 KB
#6671	`StartStopWithChild`	net472	16.1μs	43.2ns	162ns	1.05	0.325	0.103	6.22 KB

Benchmarks.Trace.AgentWriterBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`WriteAndFlushEnrichedTraces`	net6.0	491μs	526ns	2.04μs	0	2.7 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	648μs	459ns	1.78μs	0	2.7 KB
master	`WriteAndFlushEnrichedTraces`	net472	870μs	491ns	1.77μs	0.431	3.3 KB
#6671	`WriteAndFlushEnrichedTraces`	net6.0	507μs	499ns	1.87μs	0	2.7 KB
#6671	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	652μs	347ns	1.3μs	0	2.7 KB
#6671	`WriteAndFlushEnrichedTraces`	net472	864μs	339ns	1.31μs	0.431	3.3 KB

Benchmarks.Trace.AspNetCoreBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`SendRequest`	net6.0	130μs	525ns	2.03μs	0.198	14.47 KB
master	`SendRequest`	netcoreapp3.1	143μs	500ns	1.94μs	0.218	17.27 KB
master	`SendRequest`	net472	0.00978ns	0.00216ns	0.00835ns	0	0 b
#6671	`SendRequest`	net6.0	128μs	349ns	1.35μs	0.186	14.47 KB
#6671	`SendRequest`	netcoreapp3.1	142μs	558ns	2.16μs	0.217	17.28 KB
#6671	`SendRequest`	net472	0.00464ns	0.00138ns	0.00534ns	0	0 b

Benchmarks.Trace.CIVisibilityProtocolWriterBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Gen 2	Allocated
master	`WriteAndFlushEnrichedTraces`	net6.0	583μs	3.25μs	20.3μs	0.598	0	0	41.63 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	651μs	2.86μs	11.1μs	0.316	0	0	41.74 KB
master	`WriteAndFlushEnrichedTraces`	net472	836μs	3.85μs	14.4μs	8.19	2.59	0.431	53.27 KB
#6671	`WriteAndFlushEnrichedTraces`	net6.0	579μs	3.22μs	21.1μs	0.573	0	0	41.6 KB
#6671	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	676μs	3.65μs	21μs	0.347	0	0	41.65 KB
#6671	`WriteAndFlushEnrichedTraces`	net472	862μs	2.98μs	11.5μs	8.45	2.53	0.422	53.31 KB

Benchmarks.Trace.DbCommandBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`ExecuteNonQuery`	net6.0	1.35μs	1.2ns	4.65ns	0.0143	0	1.02 KB
master	`ExecuteNonQuery`	netcoreapp3.1	1.71μs	1.13ns	4.36ns	0.0138	0	1.02 KB
master	`ExecuteNonQuery`	net472	2.11μs	2.75ns	10.7ns	0.156	0.00106	987 B
#6671	`ExecuteNonQuery`	net6.0	1.38μs	1.45ns	5.63ns	0.0138	0	1.02 KB
#6671	`ExecuteNonQuery`	netcoreapp3.1	1.8μs	1.3ns	5.03ns	0.0138	0	1.02 KB
#6671	`ExecuteNonQuery`	net472	2.07μs	1.68ns	6.27ns	0.156	0.00104	987 B

Benchmarks.Trace.ElasticsearchBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`CallElasticsearch`	net6.0	1.31μs	0.593ns	2.22ns	0.0139	976 B
master	`CallElasticsearch`	netcoreapp3.1	1.54μs	0.821ns	3.18ns	0.0128	976 B
master	`CallElasticsearch`	net472	2.51μs	1.61ns	6.23ns	0.157	995 B
master	`CallElasticsearchAsync`	net6.0	1.29μs	0.767ns	2.97ns	0.013	952 B
master	`CallElasticsearchAsync`	netcoreapp3.1	1.65μs	0.879ns	3.17ns	0.014	1.02 KB
master	`CallElasticsearchAsync`	net472	2.51μs	0.746ns	2.69ns	0.167	1.05 KB
#6671	`CallElasticsearch`	net6.0	1.22μs	0.595ns	2.31ns	0.014	976 B
#6671	`CallElasticsearch`	netcoreapp3.1	1.56μs	0.643ns	2.41ns	0.0133	976 B
#6671	`CallElasticsearch`	net472	2.54μs	1.72ns	6.64ns	0.158	995 B
#6671	`CallElasticsearchAsync`	net6.0	1.27μs	0.588ns	2.28ns	0.0134	952 B
#6671	`CallElasticsearchAsync`	netcoreapp3.1	1.67μs	0.615ns	2.38ns	0.0134	1.02 KB
#6671	`CallElasticsearchAsync`	net472	2.52μs	2ns	7.5ns	0.166	1.05 KB

Benchmarks.Trace.GraphQLBenchmark - Slower ⚠️ Same allocations ✔️

Slower ⚠️ in #6671

Benchmark	diff/base	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.GraphQLBenchmark.ExecuteAsync‑net6.0	1.130	1,185.63	1,339.28

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`ExecuteAsync`	net6.0	1.19μs	0.383ns	1.48ns	0.0137	952 B
master	`ExecuteAsync`	netcoreapp3.1	1.62μs	1.5ns	5.79ns	0.0122	952 B
master	`ExecuteAsync`	net472	1.84μs	0.6ns	2.16ns	0.145	915 B
#6671	`ExecuteAsync`	net6.0	1.34μs	0.673ns	2.52ns	0.0129	952 B
#6671	`ExecuteAsync`	netcoreapp3.1	1.65μs	1.01ns	3.65ns	0.0126	952 B
#6671	`ExecuteAsync`	net472	1.88μs	0.691ns	2.68ns	0.145	915 B

Benchmarks.Trace.HttpClientBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`SendAsync`	net6.0	4.42μs	1.17ns	4.37ns	0.0309	2.31 KB
master	`SendAsync`	netcoreapp3.1	5.35μs	5.4ns	19.5ns	0.0376	2.85 KB
master	`SendAsync`	net472	7.42μs	1.17ns	4.37ns	0.494	3.12 KB
#6671	`SendAsync`	net6.0	4.43μs	12.1ns	46.9ns	0.033	2.31 KB
#6671	`SendAsync`	netcoreapp3.1	5.47μs	2.57ns	9.97ns	0.0383	2.85 KB
#6671	`SendAsync`	net472	7.48μs	1.77ns	6.85ns	0.495	3.12 KB

Benchmarks.Trace.ILoggerBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net6.0	1.47μs	0.602ns	2.33ns	0.0227	1.64 KB
master	`EnrichedLog`	netcoreapp3.1	2.18μs	0.913ns	3.41ns	0.0216	1.64 KB
master	`EnrichedLog`	net472	2.54μs	0.954ns	3.57ns	0.249	1.57 KB
#6671	`EnrichedLog`	net6.0	1.52μs	0.984ns	3.68ns	0.0234	1.64 KB
#6671	`EnrichedLog`	netcoreapp3.1	2.14μs	1.93ns	7.23ns	0.0225	1.64 KB
#6671	`EnrichedLog`	net472	2.62μs	7.64ns	29.6ns	0.249	1.57 KB

Benchmarks.Trace.Log4netBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`EnrichedLog`	net6.0	113μs	140ns	525ns	0.0562	0	4.28 KB
master	`EnrichedLog`	netcoreapp3.1	119μs	152ns	590ns	0.0595	0	4.28 KB
master	`EnrichedLog`	net472	149μs	119ns	460ns	0.669	0.223	4.46 KB
#6671	`EnrichedLog`	net6.0	113μs	131ns	490ns	0	0	4.28 KB
#6671	`EnrichedLog`	netcoreapp3.1	118μs	118ns	455ns	0.0588	0	4.28 KB
#6671	`EnrichedLog`	net472	149μs	162ns	629ns	0.67	0.223	4.46 KB

Benchmarks.Trace.NLogBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net6.0	3.09μs	0.966ns	3.74ns	0.0307	2.2 KB
master	`EnrichedLog`	netcoreapp3.1	4.1μs	1.99ns	7.69ns	0.0287	2.2 KB
master	`EnrichedLog`	net472	4.82μs	1.91ns	7.15ns	0.319	2.02 KB
#6671	`EnrichedLog`	net6.0	2.98μs	0.852ns	3.3ns	0.03	2.2 KB
#6671	`EnrichedLog`	netcoreapp3.1	4.03μs	2.05ns	7.95ns	0.0282	2.2 KB
#6671	`EnrichedLog`	net472	4.99μs	1.24ns	4.8ns	0.321	2.02 KB

Benchmarks.Trace.RedisBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`SendReceive`	net6.0	1.33μs	0.776ns	3.01ns	0.0159	1.14 KB
master	`SendReceive`	netcoreapp3.1	1.88μs	2.78ns	10.8ns	0.015	1.14 KB
master	`SendReceive`	net472	2.05μs	0.792ns	2.96ns	0.183	1.16 KB
#6671	`SendReceive`	net6.0	1.38μs	0.656ns	2.36ns	0.0159	1.14 KB
#6671	`SendReceive`	netcoreapp3.1	1.78μs	0.842ns	2.92ns	0.0153	1.14 KB
#6671	`SendReceive`	net472	2.18μs	6.59ns	25.5ns	0.184	1.16 KB

Benchmarks.Trace.SerilogBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net6.0	2.88μs	0.712ns	2.76ns	0.0217	1.6 KB
master	`EnrichedLog`	netcoreapp3.1	3.82μs	1.98ns	7.67ns	0.021	1.65 KB
master	`EnrichedLog`	net472	4.29μs	4.29ns	16ns	0.322	2.04 KB
#6671	`EnrichedLog`	net6.0	2.87μs	1.54ns	5.98ns	0.0214	1.6 KB
#6671	`EnrichedLog`	netcoreapp3.1	3.7μs	2.22ns	8.6ns	0.0222	1.65 KB
#6671	`EnrichedLog`	net472	4.21μs	4.31ns	16.7ns	0.324	2.04 KB

Benchmarks.Trace.SpanBenchmark - Faster 🎉 Same allocations ✔️

Faster 🎉 in #6671

Benchmark	base/diff	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.SpanBenchmark.StartFinishScope‑netcoreapp3.1	1.139	743.90	653.13

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`StartFinishSpan`	net6.0	397ns	0.466ns	1.8ns	0.00815	576 B
master	`StartFinishSpan`	netcoreapp3.1	607ns	0.892ns	3.45ns	0.0076	576 B
master	`StartFinishSpan`	net472	589ns	0.939ns	3.51ns	0.0918	578 B
master	`StartFinishScope`	net6.0	485ns	0.717ns	2.78ns	0.00983	696 B
master	`StartFinishScope`	netcoreapp3.1	742ns	2.23ns	8.62ns	0.00941	696 B
master	`StartFinishScope`	net472	828ns	1.73ns	6.72ns	0.104	658 B
#6671	`StartFinishSpan`	net6.0	424ns	0.522ns	2.02ns	0.00815	576 B
#6671	`StartFinishSpan`	netcoreapp3.1	582ns	0.871ns	3.14ns	0.00796	576 B
#6671	`StartFinishSpan`	net472	567ns	1.23ns	4.76ns	0.0918	578 B
#6671	`StartFinishScope`	net6.0	484ns	1.22ns	4.72ns	0.00978	696 B
#6671	`StartFinishScope`	netcoreapp3.1	652ns	1.49ns	5.78ns	0.00934	696 B
#6671	`StartFinishScope`	net472	873ns	1.74ns	6.74ns	0.104	658 B

Benchmarks.Trace.TraceAnnotationsBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`RunOnMethodBegin`	net6.0	643ns	0.873ns	3.38ns	0.0096	696 B
master	`RunOnMethodBegin`	netcoreapp3.1	947ns	1.87ns	7.23ns	0.00917	696 B
master	`RunOnMethodBegin`	net472	1.09μs	2.22ns	8.29ns	0.105	658 B
#6671	`RunOnMethodBegin`	net6.0	635ns	1.59ns	6.14ns	0.00987	696 B
#6671	`RunOnMethodBegin`	netcoreapp3.1	938ns	2.21ns	8.54ns	0.00948	696 B
#6671	`RunOnMethodBegin`	net472	1.05μs	2.35ns	9.09ns	0.104	658 B

Try to reduce flake

958c11e

andrewlock added the area:builds project files, build scripts, pipelines, versioning, releases, packages label Feb 17, 2025

andrewlock requested review from a team as code owners February 17, 2025 09:02

Fix join vs combine faffing

5bf244a

kevingosse approved these changes Feb 17, 2025

View reviewed changes

andrewlock merged commit 7d24b3d into master Feb 17, 2025
139 of 142 checks passed

andrewlock deleted the andrew/ci/fix-fleet-installer-flake branch February 17, 2025 12:00

github-actions bot added this to the vNext-v3 milestone Feb 17, 2025

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Reduce flake in Fleet installer tests #6671

Reduce flake in Fleet installer tests #6671

andrewlock commented Feb 17, 2025

andrewlock commented Feb 17, 2025 •

edited

Loading

andrewlock commented Feb 17, 2025

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Slower ⚠️ in #6671

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Faster 🎉 in #6671

Raw results

Raw results

Reduce flake in Fleet installer tests #6671

Reduce flake in Fleet installer tests #6671

Conversation

andrewlock commented Feb 17, 2025

Summary of changes

Reason for change

Implementation details

Test coverage

Other details

andrewlock commented Feb 17, 2025 • edited Loading

Execution-Time Benchmarks Report ⏱️

andrewlock commented Feb 17, 2025

Benchmarks Report for tracer 🐌

Benchmark details

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Slower ⚠️ in #6671

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Faster 🎉 in #6671

Raw results

Raw results

andrewlock commented Feb 17, 2025 •

edited

Loading