Crash in BDN with System.InvalidOperationException

[DrewScoggins]

I have seen this error in both Benchmark: GetService.ServiceScope and Benchmark: Brotli.Compress

@adamsitnik

[2021/02/18 02:12:00][INFO] // Benchmark Process 3336 has exited with code -1073741819
[2021/02/18 02:12:00][INFO] Unhandled exception. System.InvalidOperationException: Sequence contains no matching element
[2021/02/18 02:12:00][INFO]    at System.Linq.ThrowHelper.ThrowNoMatchException()
[2021/02/18 02:12:00][INFO]    at BenchmarkDotNet.Running.BenchmarkRunnerClean.Execute(ILogger logger, BenchmarkCase benchmarkCase, BenchmarkId benchmarkId, IToolchain toolchain, BuildResult buildResult, IResolver resolver)
[2021/02/18 02:12:00][INFO]    at BenchmarkDotNet.Running.BenchmarkRunnerClean.RunCore(BenchmarkCase benchmarkCase, BenchmarkId benchmarkId, ILogger logger, IResolver resolver, BuildResult buildResult)
[2021/02/18 02:12:00][INFO]    at BenchmarkDotNet.Running.BenchmarkRunnerClean.Run(BenchmarkRunInfo benchmarkRunInfo, Dictionary`2 buildResults, IResolver resolver, ILogger logger, List`1 artifactsToCleanup, String resultsFolderPath, String logFilePath, StartedClock& runChronometer)
[2021/02/18 02:12:00][INFO]    at BenchmarkDotNet.Running.BenchmarkRunnerClean.Run(BenchmarkRunInfo[] benchmarkRunInfos)
[2021/02/18 02:12:00][INFO]    at BenchmarkDotNet.Running.BenchmarkSwitcher.RunWithDirtyAssemblyResolveHelper(String[] args, IConfig config)
[2021/02/18 02:12:00][INFO]    at BenchmarkDotNet.Running.BenchmarkSwitcher.Run(String[] args, IConfig config)
[2021/02/18 02:12:00][INFO]    at MicroBenchmarks.Program.Main(String[] args) in C:\dotnetbuild\work\A47608E7\p\performance\src\benchmarks\micro\Program.cs:line 41

[adamsitnik]

@DrewScoggins do you have full logs for these benchmarks? I would like to know what happened before BDN crashed (was the benchmark executed etc)

[DrewScoggins]

Here is how you can get the full logs. You will just need to get an access key from https://helix.dot.net

https://helix.dot.net/api/2019-06-17/jobs/b681507d-5ac8-4387-a130-ed6e1549058a/workitems/release.Partition28/console?access_token=

https://helix.dot.net/api/2019-06-17/jobs/36bff71e-555e-44f3-8b6f-4cd1a476d630/workitems/release.Partition0/console?access_token=

[adamsitnik]

@DrewScoggins thanks for providing the links to logs.

From what I can see it looks like the benchmark process exited with -1073741819 which translates to 0xc0000005 which is Access Violation

[2021/02/25 17:42:50][INFO] 
[2021/02/25 17:42:50][INFO] // Benchmark Process Environment Information:
[2021/02/25 17:42:50][INFO] // Runtime=.NET 6.0.0 (6.0.21.12505), X64 RyuJIT
[2021/02/25 17:42:50][INFO] // GC=Concurrent Workstation
[2021/02/25 17:42:50][INFO] // Job: Job-OYYMFH(PowerPlanMode=00000000-0000-0000-0000-000000000000, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1)
[2021/02/25 17:42:50][INFO] 
[2021/02/25 17:42:50][INFO] OverheadJitting  1: 1 op, 247400.00 ns, 247.4000 us/op
[2021/02/25 17:42:50][INFO] WorkloadJitting  1: 1 op, 244100.00 ns, 244.1000 us/op
[2021/02/25 17:42:50][INFO] 
[2021/02/25 17:42:50][INFO] OverheadJitting  2: 16 op, 204300.00 ns, 12.7688 us/op
[2021/02/25 17:42:50][INFO] WorkloadJitting  2: 16 op, 875700.00 ns, 54.7313 us/op
[2021/02/25 17:42:50][INFO] 
[2021/02/25 17:42:50][INFO] WorkloadPilot    1: 16 op, 642800.00 ns, 40.1750 us/op
[2021/02/25 17:42:51][INFO] WorkloadPilot    2: 6224 op, 266725800.00 ns, 42.8544 us/op
[2021/02/25 17:42:51][INFO] WorkloadPilot    3: 5840 op, 247113500.00 ns, 42.3140 us/op
[2021/02/25 17:42:51][INFO] WorkloadPilot    4: 5920 op, 246479000.00 ns, 41.6350 us/op
[2021/02/25 17:42:51][INFO] WorkloadPilot    5: 6016 op, 151042500.00 ns, 25.1068 us/op
[2021/02/25 17:42:51][INFO] WorkloadPilot    6: 9968 op, 209802700.00 ns, 21.0476 us/op
[2021/02/25 17:42:52][INFO] WorkloadPilot    7: 11888 op, 220794100.00 ns, 18.5729 us/op
[2021/02/25 17:42:52][INFO] WorkloadPilot    8: 13472 op, 239804200.00 ns, 17.8002 us/op
[2021/02/25 17:42:52][INFO] WorkloadPilot    9: 14048 op, 252576100.00 ns, 17.9795 us/op
[2021/02/25 17:42:52][INFO] WorkloadPilot   10: 13920 op, 216190100.00 ns, 15.5309 us/op
[2021/02/25 17:42:53][INFO] WorkloadPilot   11: 16112 op, 220560300.00 ns, 13.6892 us/op
[2021/02/25 17:42:53][INFO] WorkloadPilot   12: 18272 op, 260518500.00 ns, 14.2578 us/op
[2021/02/25 17:42:53][INFO] 
[2021/02/25 17:42:53][INFO] OverheadWarmup   1: 18272 op, 40500.00 ns, 2.2165 ns/op
[2021/02/25 17:42:53][INFO] OverheadWarmup   2: 18272 op, 39300.00 ns, 2.1508 ns/op
[2021/02/25 17:42:53][INFO] OverheadWarmup   3: 18272 op, 38800.00 ns, 2.1235 ns/op
[2021/02/25 17:42:53][INFO] OverheadWarmup   4: 18272 op, 39700.00 ns, 2.1727 ns/op
[2021/02/25 17:42:53][INFO] OverheadWarmup   5: 18272 op, 39600.00 ns, 2.1673 ns/op
[2021/02/25 17:42:53][INFO] OverheadWarmup   6: 18272 op, 39600.00 ns, 2.1673 ns/op
[2021/02/25 17:42:53][INFO] OverheadWarmup   7: 18272 op, 38800.00 ns, 2.1235 ns/op
[2021/02/25 17:42:53][INFO] 
[2021/02/25 17:42:53][INFO] OverheadActual   1: 18272 op, 40100.00 ns, 2.1946 ns/op
[2021/02/25 17:42:53][INFO] OverheadActual   2: 18272 op, 39600.00 ns, 2.1673 ns/op
[2021/02/25 17:42:53][INFO] OverheadActual   3: 18272 op, 39600.00 ns, 2.1673 ns/op
[2021/02/25 17:42:53][INFO] OverheadActual   4: 18272 op, 39900.00 ns, 2.1837 ns/op
[2021/02/25 17:42:53][INFO] OverheadActual   5: 18272 op, 39600.00 ns, 2.1673 ns/op
[2021/02/25 17:42:53][INFO] OverheadActual   6: 18272 op, 39600.00 ns, 2.1673 ns/op
[2021/02/25 17:42:53][INFO] OverheadActual   7: 18272 op, 39500.00 ns, 2.1618 ns/op
[2021/02/25 17:42:53][INFO] OverheadActual   8: 18272 op, 39900.00 ns, 2.1837 ns/op
[2021/02/25 17:42:53][INFO] OverheadActual   9: 18272 op, 39100.00 ns, 2.1399 ns/op
[2021/02/25 17:42:53][INFO] OverheadActual  10: 18272 op, 39500.00 ns, 2.1618 ns/op
[2021/02/25 17:42:53][INFO] OverheadActual  11: 18272 op, 39800.00 ns, 2.1782 ns/op
[2021/02/25 17:42:53][INFO] OverheadActual  12: 18272 op, 40000.00 ns, 2.1891 ns/op
[2021/02/25 17:42:53][INFO] OverheadActual  13: 18272 op, 39800.00 ns, 2.1782 ns/op
[2021/02/25 17:42:53][INFO] OverheadActual  14: 18272 op, 39100.00 ns, 2.1399 ns/op
[2021/02/25 17:42:53][INFO] OverheadActual  15: 18272 op, 39900.00 ns, 2.1837 ns/op
[2021/02/25 17:42:53][INFO] 
[2021/02/25 17:42:54][INFO] // Benchmark Process 2108 has exited with code -1073741819
[2021/02/25 17:42:54][INFO] Unhandled exception. System.InvalidOperationException: Sequence contains no matching element
[2021/02/25 17:42:54][INFO]    at System.Linq.ThrowHelper.ThrowNoMatchException()
[2021/02/25 17:42:54][INFO]    at BenchmarkDotNet.Running.BenchmarkRunnerClean.Execute(ILogger logger, BenchmarkCase benchmarkCase, BenchmarkId benchmarkId, IToolchain toolchain, BuildResult buildResult, IResolver resolver)
[2021/02/25 17:42:54][INFO]    at BenchmarkDotNet.Running.BenchmarkRunnerClean.RunCore(BenchmarkCase benchmarkCase, BenchmarkId benchmarkId, ILogger logger, IResolver resolver, BuildResult buildResult)
[2021/02/25 17:42:54][INFO]    at BenchmarkDotNet.Running.BenchmarkRunnerClean.Run(BenchmarkRunInfo benchmarkRunInfo, Dictionary`2 buildResults, IResolver resolver, ILogger logger, List`1 artifactsToCleanup, String resultsFolderPath, String logFilePath, StartedClock& runChronometer)
[2021/02/25 17:42:54][INFO]    at BenchmarkDotNet.Running.BenchmarkRunnerClean.Run(BenchmarkRunInfo[] benchmarkRunInfos)
[2021/02/25 17:42:54][INFO]    at BenchmarkDotNet.Running.BenchmarkSwitcher.RunWithDirtyAssemblyResolveHelper(String[] args, IConfig config)
[2021/02/25 17:42:54][INFO]    at BenchmarkDotNet.Running.BenchmarkSwitcher.Run(String[] args, IConfig config)
[2021/02/25 17:42:54][INFO]    at MicroBenchmarks.Program.Main

[2021/02/18 02:12:00][INFO] OverheadJitting  1: 1 op, 537000.00 ns, 537.0000 us/op
[2021/02/18 02:12:00][INFO] WorkloadJitting  1: 1 op, 6767100.00 ns, 6.7671 ms/op
[2021/02/18 02:12:00][INFO] 
[2021/02/18 02:12:00][INFO] OverheadJitting  2: 16 op, 731100.00 ns, 45.6938 us/op
[2021/02/18 02:12:00][INFO] WorkloadJitting  2: 16 op, 2527400.00 ns, 157.9625 us/op
[2021/02/18 02:12:00][INFO] 
[2021/02/18 02:12:00][INFO] WorkloadPilot    1: 16 op, 7800.00 ns, 487.5000 ns/op
[2021/02/18 02:12:00][INFO] // Benchmark Process 3336 has exited with code -1073741819
[2021/02/18 02:12:00][INFO] Unhandled exception. System.InvalidOperationException: Sequence contains no matching element
[2021/02/18 02:12:00][INFO]    at System.Linq.ThrowHelper.ThrowNoMatchException()
[2021/02/18 02:12:00][INFO]    at BenchmarkDotNet.Running.BenchmarkRunnerClean.Execute(ILogger logger, BenchmarkCase benchmarkCase, BenchmarkId benchmarkId, IToolchain toolchain, BuildResult buildResult, IResolver resolver)
[2021/02/18 02:12:00][INFO]    at BenchmarkDotNet.Running.BenchmarkRunnerClean.RunCore(BenchmarkCase benchmarkCase, BenchmarkId benchmarkId, ILogger logger, IResolver resolver, BuildResult buildResult)
[2021/02/18 02:12:00][INFO]    at BenchmarkDotNet.Running.BenchmarkRunnerClean.Run(BenchmarkRunInfo benchmarkRunInfo, Dictionary`2 buildResults, IResolver resolver, ILogger logger, List`1 artifactsToCleanup, String resultsFolderPath, String logFilePath, StartedClock& runChronometer)
[2021/02/18 02:12:00][INFO]    at BenchmarkDotNet.Running.BenchmarkRunnerClean.Run(BenchmarkRunInfo[] benchmarkRunInfos)
[2021/02/18 02:12:00][INFO]    at BenchmarkDotNet.Running.BenchmarkSwitcher.RunWithDirtyAssemblyResolveHelper(String[] args, IConfig config)
[2021/02/18 02:12:00][INFO]    at BenchmarkDotNet.Running.BenchmarkSwitcher.Run(String[] args, IConfig config)

It most probably means that we have hit a bug in the runtime itself.

I've added an issue to BenchmarkDotNet backlog: dotnet/BenchmarkDotNet#1661 to stop gracefully when benchmark fails with an exception that can not be caught by a catch block. But even if we implement it and the runtime bug still exists, we won't be able to run the benchmarks (BDN will stop as it's configured to stop on the first failure)