Long test time for Perf_Timer.[A]synchronousContention tests

[LoopedBard3]

Arm runs for the Perf_Timer.SynchronousContention and Perf_Timer.AsynchronousContention seem to be taking a very long time to run compared to other tests. I have not figured out if this is normal yet, but even if it is, it is causing the workitems to be killed before finishing the test. Here is a AsyncronousContention test run showing the long op time:

[2022/05/09 02:41:58][INFO] // Found 1 benchmarks:
[2022/05/09 02:41:58][INFO] //   Perf_Timer.AsynchronousContention: Job-ZFDVZO(PowerPlanMode=00000000-0000-0000-0000-000000000000, Toolchain=CoreRun, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1)
[2022/05/09 02:41:58][INFO] 
[2022/05/09 02:41:58][INFO] // **************************
[2022/05/09 02:41:58][INFO] // Benchmark: Perf_Timer.AsynchronousContention: Job-ZFDVZO(PowerPlanMode=00000000-0000-0000-0000-000000000000, Toolchain=CoreRun, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1)
[2022/05/09 02:41:58][INFO] // *** Execute ***
[2022/05/09 02:41:58][INFO] // Launch: 1 / 1
[2022/05/09 02:41:58][INFO] // Execute: d:\h\w\ACFA0966\p\ace87cfe-f5c4-4b97-b823-ad0e6258ba8e\CoreRun.exe 8db282dc-8d31-42a9-97cb-77e08fc363be.dll --benchmarkName System.Threading.Tests.Perf_Timer.AsynchronousContention --job "PowerPlanMode=00000000-0000-0000-0000-000000000000, Toolchain=CoreRun, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1" --benchmarkId 149 in d:\h\w\ACFA0966\w\A39908F8\e\performance\artifacts\bin\MicroBenchmarks\Release\net7.0\8db282dc-8d31-42a9-97cb-77e08fc363be\bin\Release\net7.0\publish
[2022/05/09 02:41:58][INFO] // BeforeAnythingElse
[2022/05/09 02:41:58][INFO] 
[2022/05/09 02:41:58][INFO] // Benchmark Process Environment Information:
[2022/05/09 02:41:58][INFO] // Runtime=.NET 7.0.0 (42.42.42.42424), Arm64 RyuJIT
[2022/05/09 02:41:58][INFO] // GC=Concurrent Workstation
[2022/05/09 02:41:58][INFO] // Job: Job-ULUNGH(PowerPlanMode=00000000-0000-0000-0000-000000000000, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1)
[2022/05/09 02:41:58][INFO] 
[2022/05/09 02:41:58][INFO] OverheadJitting  1: 1 op, 372480.00 ns, 372.4800 us/op
[2022/05/09 02:49:03][INFO] WorkloadJitting  1: 1 op, 424645431360.00 ns, 424.6454 s/op
[2022/05/09 02:49:03][INFO] 
[2022/05/09 02:56:00][INFO] WorkloadWarmup   1: 1 op, 417565330720.00 ns, 417.5653 s/op
[2022/05/09 02:56:00][INFO] 
[2022/05/09 02:56:00][INFO] // BeforeActualRun
[2022/05/09 03:02:57][INFO] WorkloadActual   1: 1 op, 417093916600.00 ns, 417.0939 s/op
[2022/05/09 03:09:59][INFO] WorkloadActual   2: 1 op, 421157506560.00 ns, 421.1575 s/op
[2022/05/09 03:16:59][INFO] WorkloadActual   3: 1 op, 420808784080.00 ns, 420.8088 s/op
[2022/05/09 03:23:59][INFO] WorkloadActual   4: 1 op, 419575565840.00 ns, 419.5756 s/op
[2022/05/09 03:30:59][INFO] WorkloadActual   5: 1 op, 419949437040.00 ns, 419.9494 s/op
[2022/05/09 03:37:56][INFO] WorkloadActual   6: 1 op, 416664931840.00 ns, 416.6649 s/op
[2022/05/09 03:44:52][INFO] WorkloadActual   7: 1 op, 416151153800.00 ns, 416.1512 s/op
[2022/05/09 03:51:48][INFO] WorkloadActual   8: 1 op, 415996931200.00 ns, 415.9969 s/op
[2022/05/09 03:58:44][INFO] WorkloadActual   9: 1 op, 415999383760.00 ns, 415.9994 s/op
[2022/05/09 04:05:40][INFO] WorkloadActual  10: 1 op, 416257243000.00 ns, 416.2572 s/op
[2022/05/09 04:12:35][INFO] WorkloadActual  11: 1 op, 415429568000.00 ns, 415.4296 s/op
[2022/05/09 04:19:31][INFO] WorkloadActual  12: 1 op, 415642335840.00 ns, 415.6423 s/op
[2022/05/09 04:26:27][INFO] WorkloadActual  13: 1 op, 415605291040.00 ns, 415.6053 s/op
[2022/05/09 04:33:25][INFO] WorkloadActual  14: 1 op, 418414539880.00 ns, 418.4145 s/op
[2022/05/09 04:40:21][INFO] WorkloadActual  15: 1 op, 415432427200.00 ns, 415.4324 s/op

[LoopedBard3]

cc @AndyAyersMS and @kunalspathak. Through some more looking, this seems be occurring only mostly on the Ampere machines (linux is 10x surface pro X machines) and not the Surface Pro X Machines. It is taking about 100x longer on the ampere machines. The run itself is https://dev.azure.com/dnceng/internal/_build/results?buildId=1759395&view=results and they cause the only failures.

[AndyAyersMS]

These tests create 1,000,000 timers X number of cores. Amperes have 80 cores. So, lots of timers. Suspect something is amiss with the synchronization scaling here. Likely the runtime team needs to take a look. cc @mangod9

In the meantime, we might consider disabling those tests (for just the Amperes if possible) so we can get the rest of the data.

[mangod9]

yeah makes sense to disable these tests on ampere. @stephentoub @kouvel as FYI.

[kunalspathak]

@kouvel - can you verify if this benchmark is improved with #69386?

[kouvel]

Only 80 tasks are scheduled so dotnet/runtime#69386 wouldn't affect this benchmark. Maybe timer creation is not scaling well.

[LoopedBard3]

This appears to have been fixed, runs are now taking ~46 s/op instead of ~400.