Open
Description
Benchmarks Perf_Timer.AsynchronousContention and Perf_Timer.SynchronousContention are running very slow in dotnet-runtime-perf-slow on arm64/Mono/Interpreter pipeline (Performance Linux arm64 release mono Interpreter micro_mono perfampere NoJS False).
Trying to reproduce it on similar machine (VM in Azure - Ubuntu 20.04+arm64) was not successful. I and @BrzVlad were not able to build the runtime and run the benchmark on Helix machine.
This is recent run:
[2022/11/06 09:20:40][INFO] // Found 1 benchmarks:
[2022/11/06 09:20:40][INFO] // Perf_Timer.AsynchronousContention: Job-WRTDBJ(PowerPlanMode=00000000-0000-0000-0000-000000000000, Toolchain=CoreRun, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1)
[2022/11/06 09:20:40][INFO]
[2022/11/06 09:20:40][INFO] // **************************
[2022/11/06 09:20:40][INFO] // Benchmark: Perf_Timer.AsynchronousContention: Job-WRTDBJ(PowerPlanMode=00000000-0000-0000-0000-000000000000, Toolchain=CoreRun, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1)
[2022/11/06 09:20:40][INFO] // *** Execute ***
[2022/11/06 09:20:40][INFO] // Launch: 1 / 1
[2022/11/06 09:20:40][INFO] // Execute: /home/helixbot/work/ABE0092A/p/dotnet-mono/shared/Microsoft.NETCore.App/e2174923-60b2-43dd-b6a9-8441df07c287/corerun b5a5684a-08f5-4df4-b63f-edc7eea54efc.dll --anonymousPipes 541 542 --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 /home/helixbot/work/ABE0092A/w/C6760A99/e/performance/artifacts/bin/MicroBenchmarks/Release/net8.0/b5a5684a-08f5-4df4-b63f-edc7eea54efc/bin/Release/net8.0/publish
[2022/11/06 09:20:40][INFO] Failed to set up high priority. Make sure you have the right permissions. Message: Permission denied
[2022/11/06 09:20:40][INFO] // BeforeAnythingElse
[2022/11/06 09:20:40][INFO]
[2022/11/06 09:20:40][INFO] // Benchmark Process Environment Information:
[2022/11/06 09:20:40][INFO] // Runtime=.NET 8.0.0 (42.42.42.42424), Arm64 AOT
[2022/11/06 09:20:40][INFO] // GC=Non-concurrent Workstation
[2022/11/06 09:20:40][INFO] // HardwareIntrinsics=
[2022/11/06 09:20:40][INFO] // Job: Job-QZTFHS(PowerPlanMode=00000000-0000-0000-0000-000000000000, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1)
[2022/11/06 09:20:40][INFO]
[2022/11/06 09:20:40][INFO] OverheadJitting 1: 1 op, 35480.00 ns, 35.4800 us/op
[2022/11/06 09:28:22][INFO] WorkloadJitting 1: 1 op, 461892819541.00 ns, 461.8928 s/op
[2022/11/06 09:28:22][INFO]
[2022/11/06 09:35:53][INFO] WorkloadWarmup 1: 1 op, 450740774849.00 ns, 450.7408 s/op
[2022/11/06 09:35:53][INFO]
[2022/11/06 09:35:53][INFO] // BeforeActualRun
[2022/11/06 09:43:23][INFO] WorkloadActual 1: 1 op, 450043300789.00 ns, 450.0433 s/op
[2022/11/06 09:50:51][INFO] WorkloadActual 2: 1 op, 447471732038.00 ns, 447.4717 s/op
[2022/11/06 09:58:18][INFO] WorkloadActual 3: 1 op, 447013733387.00 ns, 447.0137 s/op
[2022/11/06 10:05:46][INFO] WorkloadActual 4: 1 op, 448038099850.00 ns, 448.0381 s/op
[2022/11/06 10:13:14][INFO] WorkloadActual 5: 1 op, 448591081197.00 ns, 448.5911 s/op
[2022/11/06 10:20:41][INFO] WorkloadActual 6: 1 op, 447030699880.00 ns, 447.0307 s/op
[2022/11/06 10:28:08][INFO] WorkloadActual 7: 1 op, 447022293085.00 ns, 447.0223 s/op
[2022/11/06 10:35:37][INFO] WorkloadActual 8: 1 op, 448186147351.00 ns, 448.1861 s/op
[2022/11/06 10:43:04][INFO] WorkloadActual 9: 1 op, 447640623738.00 ns, 447.6406 s/op
[2022/11/06 10:50:33][INFO] WorkloadActual 10: 1 op, 448467970186.00 ns, 448.4680 s/op
[2022/11/06 10:58:01][INFO] WorkloadActual 11: 1 op, 447736490717.00 ns, 447.7365 s/op
[2022/11/06 11:05:29][INFO] WorkloadActual 12: 1 op, 448190031399.00 ns, 448.1900 s/op
[2022/11/06 11:12:59][INFO] WorkloadActual 13: 1 op, 449815026432.00 ns, 449.8150 s/op
Killed
It's eventually killed, because pipeline runs out of time.
Below is one from September that finished. But the times are still in 167s.
[2022/09/23 21:20:32][INFO] // Found 1 benchmarks:
[2022/09/23 21:20:32][INFO] // Perf_Timer.AsynchronousContention: Job-DUILMZ(PowerPlanMode=00000000-0000-0000-0000-000000000000, Toolchain=CoreRun, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1)
[2022/09/23 21:20:32][INFO]
[2022/09/23 21:20:32][INFO] // **************************
[2022/09/23 21:20:32][INFO] // Benchmark: Perf_Timer.AsynchronousContention: Job-DUILMZ(PowerPlanMode=00000000-0000-0000-0000-000000000000, Toolchain=CoreRun, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1)
[2022/09/23 21:20:32][INFO] // *** Execute ***
[2022/09/23 21:20:32][INFO] // Launch: 1 / 1
[2022/09/23 21:20:32][INFO] // Execute: /home/helixbot/work/B2030979/p/dotnet-mono/shared/Microsoft.NETCore.App/7b7a15c3-9555-44f0-a930-533a9f2547dc/corerun 3b989c30-9124-438b-b4b7-cd4fd717963a.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 150 in /home/helixbot/work/B2030979/w/BDB30A21/e/performance/artifacts/bin/MicroBenchmarks/Release/net7.0/3b989c30-9124-438b-b4b7-cd4fd717963a/bin/Release/net7.0/publish
[2022/09/23 21:20:32][INFO] Failed to set up high priority. Make sure you have the right permissions. Message: Permission denied
[2022/09/23 21:20:32][INFO] // BeforeAnythingElse
[2022/09/23 21:20:32][INFO]
[2022/09/23 21:20:32][INFO] // Benchmark Process Environment Information:
[2022/09/23 21:20:32][INFO] // Runtime=.NET 8.0.0 (42.42.42.42424), Arm64 AOT
[2022/09/23 21:20:32][INFO] // GC=Non-concurrent Workstation
[2022/09/23 21:20:32][INFO] // HardwareIntrinsics=
[2022/09/23 21:20:33][INFO] // Job: Job-GJKJNQ(PowerPlanMode=00000000-0000-0000-0000-000000000000, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1)
[2022/09/23 21:20:33][INFO]
[2022/09/23 21:20:33][INFO] OverheadJitting 1: 1 op, 77444.00 ns, 77.4440 us/op
[2022/09/23 21:23:32][INFO] WorkloadJitting 1: 1 op, 179874620266.00 ns, 179.8746 s/op
[2022/09/23 21:23:32][INFO]
[2022/09/23 21:26:20][INFO] WorkloadWarmup 1: 1 op, 167329988104.00 ns, 167.3300 s/op
[2022/09/23 21:26:20][INFO]
[2022/09/23 21:26:20][INFO] // BeforeActualRun
[2022/09/23 21:29:07][INFO] WorkloadActual 1: 1 op, 167549719942.00 ns, 167.5497 s/op
[2022/09/23 21:31:55][INFO] WorkloadActual 2: 1 op, 167296143533.00 ns, 167.2961 s/op
[2022/09/23 21:34:42][INFO] WorkloadActual 3: 1 op, 167278742826.00 ns, 167.2787 s/op
[2022/09/23 21:37:29][INFO] WorkloadActual 4: 1 op, 167452413521.00 ns, 167.4524 s/op
[2022/09/23 21:40:17][INFO] WorkloadActual 5: 1 op, 167320729619.00 ns, 167.3207 s/op
[2022/09/23 21:43:04][INFO] WorkloadActual 6: 1 op, 167412709896.00 ns, 167.4127 s/op
[2022/09/23 21:45:52][INFO] WorkloadActual 7: 1 op, 167387006109.00 ns, 167.3870 s/op
[2022/09/23 21:48:39][INFO] WorkloadActual 8: 1 op, 167426540496.00 ns, 167.4265 s/op
[2022/09/23 21:51:26][INFO] WorkloadActual 9: 1 op, 167294036599.00 ns, 167.2940 s/op
[2022/09/23 21:54:14][INFO] WorkloadActual 10: 1 op, 167317449832.00 ns, 167.3174 s/op
[2022/09/23 21:57:01][INFO] WorkloadActual 11: 1 op, 167463292190.00 ns, 167.4633 s/op
[2022/09/23 21:59:49][INFO] WorkloadActual 12: 1 op, 167331924572.00 ns, 167.3319 s/op
[2022/09/23 22:02:36][INFO] WorkloadActual 13: 1 op, 167407704498.00 ns, 167.4077 s/op
[2022/09/23 22:05:23][INFO] WorkloadActual 14: 1 op, 167382575539.00 ns, 167.3826 s/op
[2022/09/23 22:08:11][INFO] WorkloadActual 15: 1 op, 167165982642.00 ns, 167.1660 s/op
[2022/09/23 22:08:11][INFO]
[2022/09/23 22:08:11][INFO] // AfterActualRun
[2022/09/23 22:10:58][INFO] WorkloadResult 1: 1 op, 167549719942.00 ns, 167.5497 s/op
[2022/09/23 22:10:58][INFO] WorkloadResult 2: 1 op, 167296143533.00 ns, 167.2961 s/op
[2022/09/23 22:10:58][INFO] WorkloadResult 3: 1 op, 167278742826.00 ns, 167.2787 s/op
[2022/09/23 22:10:58][INFO] WorkloadResult 4: 1 op, 167452413521.00 ns, 167.4524 s/op
[2022/09/23 22:10:58][INFO] WorkloadResult 5: 1 op, 167320729619.00 ns, 167.3207 s/op
[2022/09/23 22:10:58][INFO] WorkloadResult 6: 1 op, 167412709896.00 ns, 167.4127 s/op
[2022/09/23 22:10:58][INFO] WorkloadResult 7: 1 op, 167387006109.00 ns, 167.3870 s/op
[2022/09/23 22:10:58][INFO] WorkloadResult 8: 1 op, 167426540496.00 ns, 167.4265 s/op
[2022/09/23 22:10:58][INFO] WorkloadResult 9: 1 op, 167294036599.00 ns, 167.2940 s/op
[2022/09/23 22:10:58][INFO] WorkloadResult 10: 1 op, 167317449832.00 ns, 167.3174 s/op
[2022/09/23 22:10:58][INFO] WorkloadResult 11: 1 op, 167463292190.00 ns, 167.4633 s/op
[2022/09/23 22:10:58][INFO] WorkloadResult 12: 1 op, 167331924572.00 ns, 167.3319 s/op
[2022/09/23 22:10:58][INFO] WorkloadResult 13: 1 op, 167407704498.00 ns, 167.4077 s/op
[2022/09/23 22:10:58][INFO] WorkloadResult 14: 1 op, 167382575539.00 ns, 167.3826 s/op
[2022/09/23 22:10:58][INFO] WorkloadResult 15: 1 op, 167165982642.00 ns, 167.1660 s/op
[2022/09/23 22:10:58][INFO] GC: 3569 1 1 14720017296 1
[2022/09/23 22:10:58][INFO] Threading: 46000046 961262 1
[2022/09/23 22:10:58][INFO]
[2022/09/23 22:10:58][INFO] // AfterAll
[2022/09/23 22:10:58][INFO] // Benchmark Process 3194 has exited with code 0.
[2022/09/23 22:10:58][INFO]
[2022/09/23 22:10:58][INFO] Mean = 167.366 s, StdErr = 0.024 s (0.01%), N = 15, StdDev = 0.093 s
[2022/09/23 22:10:58][INFO] Min = 167.166 s, Q1 = 167.307 s, Median = 167.383 s, Q3 = 167.420 s, Max = 167.550 s
[2022/09/23 22:10:58][INFO] IQR = 0.113 s, LowerFence = 167.138 s, UpperFence = 167.589 s
[2022/09/23 22:10:58][INFO] ConfidenceInterval = [167.266 s; 167.466 s] (CI 99.9%), Margin = 0.100 s (0.06% of Mean)
[2022/09/23 22:10:58][INFO] Skewness = -0.11, Kurtosis = 2.65, MValue = 2
Similar behavior is for Perf_Timer.SynchronousContention.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
