Closed performanceautofiler[bot] closed 1 year ago
I couldn't figure out the best area label to add to this issue. If you have write-permissions please help me learn by adding exactly one area label.
Might also be https://github.com/dotnet/runtime/pull/76985.
Regressions on arm64 from the same commit range: https://github.com/dotnet/perf-autofiling-issues/issues/9485
I am not able to reproduce this regression. I am pretty sure that the regression is not caused by the Array.Initialize change (this method is not called by the microbenchmarks at all) nor the GC changes (the microbenchmarks do not allocate anything).
The regressed microbenchmarks typically spent 90+% time in ICU library that comes with the OS. Notice that all regressed cases have HighChars = true
or non-US cultures that forces the globalization libraries take the slow path by calling ICU library.
The most likely explanation of these regressions is that the system ICU library or globalization settings were updated on the perf machines.
Tagging subscribers to this area: @dotnet/area-system-globalization See info in area-owners.md if you want to be subscribed.
Author: | performanceautofiler[bot] |
---|---|
Assignees: | - |
Labels: | `area-System.Globalization`, `area-TypeSystem-coreclr`, `untriaged`, `Regression` |
Milestone: | - |
The issues from https://github.com/dotnet/perf-autofiling-issues/ repo resolved as duplicates look unrelated. They should be retrigged if they are real regressions.
The most likely explanation of these regressions is that the system ICU library or globalization settings were updated on the perf machines.
@DrewScoggins Any OS updates applied on perf machines in the window where this regressed?
@sblom is there anyone can help with @jkotas question https://github.com/dotnet/runtime/issues/77730#issuecomment-1302833764 as @DrewScoggins is not around?
@jkotas looking at https://pvscmdupload.blob.core.windows.net/autofilereport/autofilereports/11_01_2022/refs/heads/main_x64_alpine%203.15_Regression/System.Globalization.Tests.StringSearch.html looks the baseline and compare runs was on exact same OS version alpine 3.15
. I don't think this is an ICU issue or globalization issue at all. I know all regressions in the ICU code path, but it is not necessary to be the cause. These tests are extremely sensitive and fail most of the time for any minor changes. Alpine 3.15 always has the same ICU version https://pkgs.alpinelinux.org/packages?name=icu&branch=v3.15&repo=main&arch=&maintainer=.
Also looking at the commit diffs there are a couple of JIT fixes
Fold static readonly struct X =
Could one of these be related to regression?
@tarekgh Are you able to reproduce the regression? You can compare .NET 7 and current .NET 8 main. The regression is up to 4x so it should be very observable - if you are able to reproduce it.
exact same OS version alpine 3.15
With exact same patches? Is it possible that we have picked up new ICU as part of Alpine 3.15 servicing update?
Could one of these be related to regression?
None of the changes can explain the regression, and I am not able to reproduce it.
Are you able to reproduce the regression?
I didn't try it especially on Alpine 3.15. When you couldn't repro it, were you running on this OS?
Yes, I run it in Alpine 3.15 docker image.
@sblom is there anyone can help with @jkotas question https://github.com/dotnet/runtime/issues/77730#issuecomment-1302833764 as @DrewScoggins is not around?
@caaavik-msft Do you spot anything obvious here?
With exact same patches? Is it possible that we have picked up new ICU as part of Alpine 3.15 servicing update?
Linux distros usually do not update ICU even when having any OS minor refreshment.
@jkotas I have tried running it on the Alpine docker image comparing .NET 7.0 to .NET 8.0. I am seeing some regressions there but not much as it reported. here is every test case the first line is .NET 7.0 and next line is .NET 8.0.
[2022/11/04 03:23:29][INFO] | Method | Options | Mean | Error | StdDev | Median | Min | Max | Allocated |
[2022/11/04 03:23:29][INFO] |---------------------------- |---------------------------------- |--------------:|------------:|------------:|--------------:|--------------:|--------------:|----------:|
[2022/11/04 03:10:34][INFO] | IsPrefix_DifferentFirstChar | (en-US, None, True) | 406.573 ns | 16.1862 ns | 17.9909 ns | 403.882 ns | 362.470 ns | 437.903 ns | - |
[2022/11/04 03:23:29][INFO] | IsPrefix_DifferentFirstChar | (en-US, None, True) | 516.745 ns | 25.9868 ns | 27.8056 ns | 521.298 ns | 439.694 ns | 562.555 ns | - |
[2022/11/04 03:10:34][INFO] | IsPrefix_DifferentFirstChar | (, None, True) | 410.382 ns | 19.0013 ns | 21.8819 ns | 405.652 ns | 370.593 ns | 457.106 ns | - |
[2022/11/04 03:23:29][INFO] | IsPrefix_DifferentFirstChar | (, None, True) | 549.535 ns | 32.2888 ns | 37.1838 ns | 550.127 ns | 484.025 ns | 628.198 ns | - |
[2022/11/04 03:10:34][INFO] | IsSuffix_DifferentLastChar | (, None, True) | 591.016 ns | 31.8169 ns | 34.0438 ns | 586.958 ns | 548.398 ns | 670.420 ns | - |
[2022/11/04 03:23:29][INFO] | IsSuffix_DifferentLastChar | (, None, True) | 727.819 ns | 34.0416 ns | 37.8372 ns | 724.216 ns | 640.401 ns | 786.953 ns | - |
[2022/11/04 03:10:34][INFO] | IsSuffix_DifferentLastChar | (en-US, None, True) | 605.571 ns | 24.8139 ns | 26.5506 ns | 604.383 ns | 537.289 ns | 644.920 ns | - |
[2022/11/04 03:23:29][INFO] | IsSuffix_DifferentLastChar | (en-US, None, True) | 712.721 ns | 27.5146 ns | 29.4403 ns | 713.082 ns | 652.380 ns | 778.558 ns | - |
[2022/11/04 03:10:34][INFO] | IsPrefix_FirstHalf | (en-US, None, True) | 2,199.794 ns | 78.2627 ns | 90.1274 ns | 2,195.089 ns | 2,033.747 ns | 2,418.183 ns | - |
[2022/11/04 03:23:29][INFO] | IsPrefix_FirstHalf | (en-US, None, True) | 2,251.240 ns | 71.9746 ns | 77.0120 ns | 2,258.571 ns | 2,062.926 ns | 2,393.331 ns | - |
[2022/11/04 03:10:34][INFO] | IsPrefix_FirstHalf | (, None, True) | 2,152.662 ns | 109.0485 ns | 125.5804 ns | 2,112.266 ns | 2,011.137 ns | 2,440.574 ns | - |
[2022/11/04 03:23:29][INFO] | IsPrefix_FirstHalf | (, None, True) | 2,398.539 ns | 161.0060 ns | 185.4147 ns | 2,421.023 ns | 2,141.713 ns | 2,816.422 ns | - |
[2022/11/04 03:10:34][INFO] | IsSuffix_SecondHalf | (en-US, None, True) | 3,557.069 ns | 115.1292 ns | 127.9658 ns | 3,566.039 ns | 3,365.295 ns | 3,803.913 ns | - |
[2022/11/04 03:23:29][INFO] | IsSuffix_SecondHalf | (en-US, None, True) | 3,627.567 ns | 197.9137 ns | 219.9805 ns | 3,620.415 ns | 3,241.226 ns | 3,984.467 ns | - |
[2022/11/04 03:10:34][INFO] | IsSuffix_SecondHalf | (, None, True) | 3,569.221 ns | 192.0463 ns | 213.4589 ns | 3,537.715 ns | 3,197.809 ns | 4,076.994 ns | - |
[2022/11/04 03:23:29][INFO] | IsSuffix_SecondHalf | (, None, True) | 3,723.013 ns | 212.3613 ns | 236.0390 ns | 3,743.077 ns | 3,244.154 ns | 4,114.379 ns | - |
[2022/11/04 03:10:34][INFO] | IsPrefix_DifferentFirstChar | (, IgnoreCase, True) | 422.065 ns | 20.2881 ns | 23.3638 ns | 421.072 ns | 384.779 ns | 469.177 ns | - |
[2022/11/04 03:23:29][INFO] | IsPrefix_DifferentFirstChar | (, IgnoreCase, True) | 425.594 ns | 18.8389 ns | 20.9394 ns | 423.106 ns | 394.617 ns | 471.612 ns | - |
[2022/11/04 03:10:34][INFO] | IsSuffix_DifferentLastChar | (, IgnoreCase, True) | 598.488 ns | 33.9073 ns | 36.2804 ns | 587.273 ns | 546.458 ns | 669.598 ns | - |
[2022/11/04 03:23:29][INFO] | IsSuffix_DifferentLastChar | (, IgnoreCase, True) | 659.768 ns | 53.2271 ns | 61.2964 ns | 647.392 ns | 545.916 ns | 805.496 ns | - |
[2022/11/04 03:10:34][INFO] | IsSuffix_DifferentLastChar | (pl-PL, None, False) | 553.170 ns | 19.1877 ns | 20.5306 ns | 552.689 ns | 516.326 ns | 593.045 ns | - |
[2022/11/04 03:23:29][INFO] | IsSuffix_DifferentLastChar | (pl-PL, None, False) | 583.763 ns | 52.9284 ns | 60.9524 ns | 560.952 ns | 509.800 ns | 724.141 ns | - |
[2022/11/04 03:10:34][INFO] | IsPrefix_DifferentFirstChar | (en-US, IgnoreCase, True) | 431.577 ns | 22.0369 ns | 24.4939 ns | 425.836 ns | 400.893 ns | 476.891 ns | - |
[2022/11/04 03:23:29][INFO] | IsPrefix_DifferentFirstChar | (en-US, IgnoreCase, True) | 439.697 ns | 31.1234 ns | 34.5936 ns | 433.297 ns | 387.527 ns | 511.673 ns | - |
[2022/11/04 03:10:34][INFO] | IsPrefix_DifferentFirstChar | (pl-PL, None, False) | 475.956 ns | 40.2391 ns | 44.7256 ns | 473.165 ns | 419.992 ns | 566.089 ns | - |
[2022/11/04 03:23:29][INFO] | IsPrefix_DifferentFirstChar | (pl-PL, None, False) | 454.929 ns | 45.8240 ns | 50.9333 ns | 430.201 ns | 390.534 ns | 566.863 ns | - |
[2022/11/04 03:10:34][INFO] | IsSuffix_DifferentLastChar | (en-US, IgnoreCase, True) | 619.045 ns | 42.0035 ns | 44.9433 ns | 627.416 ns | 547.249 ns | 716.731 ns | - |
[2022/11/04 03:23:29][INFO] | IsSuffix_DifferentLastChar | (en-US, IgnoreCase, True) | 628.107 ns | 37.2037 ns | 41.3518 ns | 628.645 ns | 544.092 ns | 703.856 ns | - |
Looking at all the logs, it seems that nothing has changed with the agent that it is running on, but I'm not sure all the places to look. Here is the BDN output for IsSuffix_DifferentLastChar(Options: (, None, True))
case for the first pipeline run that showed this regression. The main thing of note I want to point out is if you look at the Pilot and Actual measurements, it briefly measures as ~690ns for some invocations, but measures as ~3-4us for the rest of the invocations. So I guess the test case suddenly became bimodal.
[2022/10/25 18:06:09][INFO] // Found 2 benchmarks:
[2022/10/25 18:06:09][INFO] // StringSearch.IsSuffix_DifferentLastChar: Job-CYQKAF(PowerPlanMode=00000000-0000-0000-0000-000000000000, Toolchain=CoreRun, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1) [Options=(, None, True)]
[2022/10/25 18:06:09][INFO] // StringSearch.IsPrefix_DifferentFirstChar: Job-CYQKAF(PowerPlanMode=00000000-0000-0000-0000-000000000000, Toolchain=CoreRun, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1) [Options=(en-US, IgnoreCase, True)]
[2022/10/25 18:06:09][INFO]
[2022/10/25 18:06:09][INFO] // **************************
[2022/10/25 18:06:09][INFO] // Benchmark: StringSearch.IsSuffix_DifferentLastChar: Job-CYQKAF(PowerPlanMode=00000000-0000-0000-0000-000000000000, Toolchain=CoreRun, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1) [Options=(, None, True)]
[2022/10/25 18:06:09][INFO] // *** Execute ***
[2022/10/25 18:06:09][INFO] // Launch: 1 / 1
[2022/10/25 18:06:09][INFO] // Execute: /home/helixbot/work/B98F09BB/p/10648328-f7fe-4c18-83d1-21d2700b7b35/corerun 64805bd7-2a9e-43e9-90cb-1738cf8fbd1c.dll --anonymousPipes 338 339 --benchmarkName "System.Globalization.Tests.StringSearch.IsSuffix_DifferentLastChar(Options: (, None, True))" --job "PowerPlanMode=00000000-0000-0000-0000-000000000000, Toolchain=CoreRun, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1" --benchmarkId 52 in /home/helixbot/work/B98F09BB/w/BC0B09C0/e/performance/artifacts/bin/MicroBenchmarks/Release/net7.0/64805bd7-2a9e-43e9-90cb-1738cf8fbd1c/bin/Release/net7.0/publish
[2022/10/25 18:06:09][INFO] Failed to set up high priority. Make sure you have the right permissions. Message: Permission denied
[2022/10/25 18:06:09][INFO] // BeforeAnythingElse
[2022/10/25 18:06:09][INFO]
[2022/10/25 18:06:09][INFO] // Benchmark Process Environment Information:
[2022/10/25 18:06:09][INFO] // Runtime=.NET 8.0.0 (42.42.42.42424), X64 RyuJIT AVX2
[2022/10/25 18:06:09][INFO] // GC=Concurrent Workstation
[2022/10/25 18:06:09][INFO] // HardwareIntrinsics=AVX2,AES,BMI1,BMI2,FMA,LZCNT,PCLMUL,POPCNT VectorSize=256
[2022/10/25 18:06:09][INFO] // Job: Job-KBMZBJ(PowerPlanMode=00000000-0000-0000-0000-000000000000, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1)
[2022/10/25 18:06:09][INFO]
[2022/10/25 18:06:09][INFO] OverheadJitting 1: 1 op, 230941.00 ns, 230.9410 us/op
[2022/10/25 18:06:09][INFO] WorkloadJitting 1: 1 op, 216624.00 ns, 216.6240 us/op
[2022/10/25 18:06:09][INFO]
[2022/10/25 18:06:09][INFO] OverheadJitting 2: 16 op, 371208.00 ns, 23.2005 us/op
[2022/10/25 18:06:09][INFO] WorkloadJitting 2: 16 op, 429880.00 ns, 26.8675 us/op
[2022/10/25 18:06:09][INFO]
[2022/10/25 18:06:09][INFO] WorkloadPilot 1: 16 op, 100525.00 ns, 6.2828 us/op
[2022/10/25 18:06:09][INFO] WorkloadPilot 2: 39792 op, 147212427.00 ns, 3.6995 us/op
[2022/10/25 18:06:09][INFO] WorkloadPilot 3: 67584 op, 142370545.00 ns, 2.1066 us/op
[2022/10/25 18:06:10][INFO] WorkloadPilot 4: 118688 op, 75623632.00 ns, 637.1633 ns/op
[2022/10/25 18:06:10][INFO] WorkloadPilot 5: 392368 op, 252409227.00 ns, 643.2972 ns/op
[2022/10/25 18:06:10][INFO] WorkloadPilot 6: 388624 op, 253916882.00 ns, 653.3742 ns/op
[2022/10/25 18:06:11][INFO] WorkloadPilot 7: 382640 op, 1383489960.00 ns, 3.6156 us/op
[2022/10/25 18:06:11][INFO]
[2022/10/25 18:06:11][INFO] OverheadWarmup 1: 382640 op, 729519.00 ns, 1.9065 ns/op
[2022/10/25 18:06:11][INFO] OverheadWarmup 2: 382640 op, 757289.00 ns, 1.9791 ns/op
[2022/10/25 18:06:11][INFO] OverheadWarmup 3: 382640 op, 729101.00 ns, 1.9054 ns/op
[2022/10/25 18:06:11][INFO] OverheadWarmup 4: 382640 op, 720159.00 ns, 1.8821 ns/op
[2022/10/25 18:06:11][INFO] OverheadWarmup 5: 382640 op, 729052.00 ns, 1.9053 ns/op
[2022/10/25 18:06:11][INFO] OverheadWarmup 6: 382640 op, 729132.00 ns, 1.9055 ns/op
[2022/10/25 18:06:11][INFO] OverheadWarmup 7: 382640 op, 716789.00 ns, 1.8733 ns/op
[2022/10/25 18:06:11][INFO]
[2022/10/25 18:06:11][INFO] OverheadActual 1: 382640 op, 731615.00 ns, 1.9120 ns/op
[2022/10/25 18:06:11][INFO] OverheadActual 2: 382640 op, 729358.00 ns, 1.9061 ns/op
[2022/10/25 18:06:11][INFO] OverheadActual 3: 382640 op, 729460.00 ns, 1.9064 ns/op
[2022/10/25 18:06:11][INFO] OverheadActual 4: 382640 op, 728959.00 ns, 1.9051 ns/op
[2022/10/25 18:06:11][INFO] OverheadActual 5: 382640 op, 729208.00 ns, 1.9057 ns/op
[2022/10/25 18:06:11][INFO] OverheadActual 6: 382640 op, 728947.00 ns, 1.9050 ns/op
[2022/10/25 18:06:11][INFO] OverheadActual 7: 382640 op, 734718.00 ns, 1.9201 ns/op
[2022/10/25 18:06:11][INFO] OverheadActual 8: 382640 op, 731743.00 ns, 1.9124 ns/op
[2022/10/25 18:06:11][INFO] OverheadActual 9: 382640 op, 726923.00 ns, 1.8998 ns/op
[2022/10/25 18:06:11][INFO] OverheadActual 10: 382640 op, 729236.00 ns, 1.9058 ns/op
[2022/10/25 18:06:11][INFO] OverheadActual 11: 382640 op, 731726.00 ns, 1.9123 ns/op
[2022/10/25 18:06:11][INFO] OverheadActual 12: 382640 op, 781324.00 ns, 2.0419 ns/op
[2022/10/25 18:06:11][INFO] OverheadActual 13: 382640 op, 729412.00 ns, 1.9063 ns/op
[2022/10/25 18:06:11][INFO] OverheadActual 14: 382640 op, 717004.00 ns, 1.8738 ns/op
[2022/10/25 18:06:11][INFO] OverheadActual 15: 382640 op, 760275.00 ns, 1.9869 ns/op
[2022/10/25 18:06:11][INFO]
[2022/10/25 18:06:12][INFO] WorkloadWarmup 1: 382640 op, 399893381.00 ns, 1.0451 us/op
[2022/10/25 18:06:12][INFO]
[2022/10/25 18:06:12][INFO] // BeforeActualRun
[2022/10/25 18:06:12][INFO] WorkloadActual 1: 382640 op, 262735632.00 ns, 686.6392 ns/op
[2022/10/25 18:06:12][INFO] WorkloadActual 2: 382640 op, 255920423.00 ns, 668.8282 ns/op
[2022/10/25 18:06:14][INFO] WorkloadActual 3: 382640 op, 1394214955.00 ns, 3.6437 us/op
[2022/10/25 18:06:15][INFO] WorkloadActual 4: 382640 op, 1510623331.00 ns, 3.9479 us/op
[2022/10/25 18:06:17][INFO] WorkloadActual 5: 382640 op, 1507687264.00 ns, 3.9402 us/op
[2022/10/25 18:06:18][INFO] WorkloadActual 6: 382640 op, 1501751826.00 ns, 3.9247 us/op
[2022/10/25 18:06:20][INFO] WorkloadActual 7: 382640 op, 1507468869.00 ns, 3.9397 us/op
[2022/10/25 18:06:21][INFO] WorkloadActual 8: 382640 op, 1508276848.00 ns, 3.9418 us/op
[2022/10/25 18:06:23][INFO] WorkloadActual 9: 382640 op, 1512935757.00 ns, 3.9539 us/op
[2022/10/25 18:06:24][INFO] WorkloadActual 10: 382640 op, 1497751858.00 ns, 3.9143 us/op
[2022/10/25 18:06:25][INFO] WorkloadActual 11: 382640 op, 1076434596.00 ns, 2.8132 us/op
[2022/10/25 18:06:27][INFO] WorkloadActual 12: 382640 op, 1510809932.00 ns, 3.9484 us/op
[2022/10/25 18:06:28][INFO] WorkloadActual 13: 382640 op, 1512777547.00 ns, 3.9535 us/op
[2022/10/25 18:06:30][INFO] WorkloadActual 14: 382640 op, 1066704408.00 ns, 2.7877 us/op
[2022/10/25 18:06:30][INFO] WorkloadActual 15: 382640 op, 254037350.00 ns, 663.9069 ns/op
[2022/10/25 18:06:31][INFO] WorkloadActual 16: 382640 op, 1510746438.00 ns, 3.9482 us/op
[2022/10/25 18:06:33][INFO] WorkloadActual 17: 382640 op, 1510605130.00 ns, 3.9478 us/op
[2022/10/25 18:06:34][INFO] WorkloadActual 18: 382640 op, 1412359749.00 ns, 3.6911 us/op
[2022/10/25 18:06:36][INFO] WorkloadActual 19: 382640 op, 1497530130.00 ns, 3.9137 us/op
[2022/10/25 18:06:37][INFO] WorkloadActual 20: 382640 op, 1503649662.00 ns, 3.9297 us/op
[2022/10/25 18:06:37][INFO]
[2022/10/25 18:06:37][INFO] // AfterActualRun
[2022/10/25 18:06:37][INFO] WorkloadResult 1: 382640 op, 262006220.00 ns, 684.7330 ns/op
[2022/10/25 18:06:37][INFO] WorkloadResult 2: 382640 op, 255191011.00 ns, 666.9219 ns/op
[2022/10/25 18:06:37][INFO] WorkloadResult 3: 382640 op, 1393485543.00 ns, 3.6418 us/op
[2022/10/25 18:06:37][INFO] WorkloadResult 4: 382640 op, 1509893919.00 ns, 3.9460 us/op
[2022/10/25 18:06:37][INFO] WorkloadResult 5: 382640 op, 1506957852.00 ns, 3.9383 us/op
[2022/10/25 18:06:37][INFO] WorkloadResult 6: 382640 op, 1501022414.00 ns, 3.9228 us/op
[2022/10/25 18:06:37][INFO] WorkloadResult 7: 382640 op, 1506739457.00 ns, 3.9377 us/op
[2022/10/25 18:06:37][INFO] WorkloadResult 8: 382640 op, 1507547436.00 ns, 3.9399 us/op
[2022/10/25 18:06:37][INFO] WorkloadResult 9: 382640 op, 1512206345.00 ns, 3.9520 us/op
[2022/10/25 18:06:37][INFO] WorkloadResult 10: 382640 op, 1497022446.00 ns, 3.9124 us/op
[2022/10/25 18:06:37][INFO] WorkloadResult 11: 382640 op, 1075705184.00 ns, 2.8113 us/op
[2022/10/25 18:06:37][INFO] WorkloadResult 12: 382640 op, 1510080520.00 ns, 3.9465 us/op
[2022/10/25 18:06:37][INFO] WorkloadResult 13: 382640 op, 1512048135.00 ns, 3.9516 us/op
[2022/10/25 18:06:37][INFO] WorkloadResult 14: 382640 op, 1065974996.00 ns, 2.7858 us/op
[2022/10/25 18:06:37][INFO] WorkloadResult 15: 382640 op, 253307938.00 ns, 662.0007 ns/op
[2022/10/25 18:06:37][INFO] WorkloadResult 16: 382640 op, 1510017026.00 ns, 3.9463 us/op
[2022/10/25 18:06:37][INFO] WorkloadResult 17: 382640 op, 1509875718.00 ns, 3.9459 us/op
[2022/10/25 18:06:37][INFO] WorkloadResult 18: 382640 op, 1411630337.00 ns, 3.6892 us/op
[2022/10/25 18:06:37][INFO] WorkloadResult 19: 382640 op, 1496800718.00 ns, 3.9118 us/op
[2022/10/25 18:06:37][INFO] WorkloadResult 20: 382640 op, 1502920250.00 ns, 3.9278 us/op
[2022/10/25 18:06:37][INFO] // GC: 0 0 0 672 382640
[2022/10/25 18:06:37][INFO] // Threading: 0 0 382640
[2022/10/25 18:06:37][INFO]
[2022/10/25 18:06:37][INFO] // AfterAll
[2022/10/25 18:06:37][INFO] // Benchmark Process 13010 has exited with code 0.
[2022/10/25 18:06:37][INFO]
[2022/10/25 18:06:37][INFO] Mean = 3.306 us, StdErr = 0.265 us (8.03%), N = 20, StdDev = 1.187 us
[2022/10/25 18:06:37][INFO] Min = 0.662 us, Q1 = 3.434 us, Median = 3.925 us, Q3 = 3.946 us, Max = 3.952 us
[2022/10/25 18:06:37][INFO] IQR = 0.512 us, LowerFence = 2.666 us, UpperFence = 4.714 us
[2022/10/25 18:06:37][INFO] ConfidenceInterval = [2.275 us; 4.337 us] (CI 99.9%), Margin = 1.031 us (31.18% of Mean)
[2022/10/25 18:06:37][INFO] Skewness = -1.55, Kurtosis = 3.7, MValue = 2.27
[2022/10/25 18:06:37][INFO]
[2022/10/25 18:06:37][INFO] // ** Remained 102 (65.8%) benchmark(s) to run. Estimated finish 2022-10-25 18:18 (0h 11m from now) **
[2022/10/25 18:06:37][INFO] // **************************
[2022/10/25 18:06:37][INFO] // Benchmark: StringSearch.IsPrefix_DifferentFirstChar: Job-CYQKAF(PowerPlanMode=00000000-0000-0000-0000-000000000000, Toolchain=CoreRun, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1) [Options=(en-US, IgnoreCase, True)]
...
[2022/10/25 18:06:44][INFO] // ***** BenchmarkRunner: Finish *****
[2022/10/25 18:06:44][INFO]
[2022/10/25 18:06:44][INFO] // * Export *
[2022/10/25 18:06:44][INFO] home/helixbot/work/B98F09BB/w/BC0B09C0/e/artifacts/BenchmarkDotNet.Artifacts/results/System.Globalization.Tests.StringSearch-report-github.md
[2022/10/25 18:06:44][INFO] home/helixbot/work/B98F09BB/w/BC0B09C0/e/artifacts/BenchmarkDotNet.Artifacts/results/System.Globalization.Tests.StringSearch-report-full.json
[2022/10/25 18:06:44][INFO] home/helixbot/work/B98F09BB/w/BC0B09C0/e/artifacts/BenchmarkDotNet.Artifacts/results/System.Globalization.Tests.StringSearch-perf-lab-report.json
[2022/10/25 18:06:44][INFO]
[2022/10/25 18:06:44][INFO] // * Detailed results *
[2022/10/25 18:06:44][INFO] StringSearch.IsSuffix_DifferentLastChar: Job-CYQKAF(PowerPlanMode=00000000-0000-0000-0000-000000000000, Toolchain=CoreRun, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1) [Options=(, None, True)]
[2022/10/25 18:06:44][INFO] Runtime = .NET 8.0.0 (42.42.42.42424), X64 RyuJIT AVX2; GC = Concurrent Workstation
[2022/10/25 18:06:44][INFO] Mean = 3.306 us, StdErr = 0.265 us (8.03%), N = 20, StdDev = 1.187 us
[2022/10/25 18:06:44][INFO] Min = 0.662 us, Q1 = 3.434 us, Median = 3.925 us, Q3 = 3.946 us, Max = 3.952 us
[2022/10/25 18:06:44][INFO] IQR = 0.512 us, LowerFence = 2.666 us, UpperFence = 4.714 us
[2022/10/25 18:06:44][INFO] ConfidenceInterval = [2.275 us; 4.337 us] (CI 99.9%), Margin = 1.031 us (31.18% of Mean)
[2022/10/25 18:06:44][INFO] Skewness = -1.55, Kurtosis = 3.7, MValue = 2.27
[2022/10/25 18:06:44][INFO] -------------------- Histogram --------------------
[2022/10/25 18:06:44][INFO] [0.088 us ; 1.247 us) | @@@
[2022/10/25 18:06:44][INFO] [1.247 us ; 2.212 us) |
[2022/10/25 18:06:44][INFO] [2.212 us ; 2.808 us) | @
[2022/10/25 18:06:44][INFO] [2.808 us ; 3.956 us) | @@@@@@@@@@@@@@@@
[2022/10/25 18:06:44][INFO] ---------------------------------------------------
...
[2022/10/25 18:06:44][INFO] // * Summary *
[2022/10/25 18:06:44][INFO]
[2022/10/25 18:06:44][INFO] BenchmarkDotNet=v0.13.2.1950-nightly, OS=alpine 3.15
[2022/10/25 18:06:44][INFO] Intel Core i7-8700 CPU 3.20GHz (Coffee Lake), 1 CPU, 12 logical and 6 physical cores
[2022/10/25 18:06:44][INFO] .NET SDK=7.0.100
[2022/10/25 18:06:44][INFO] [Host] : .NET 7.0.0 (7.0.22.51104), X64 RyuJIT AVX2
[2022/10/25 18:06:44][INFO] Job-CYQKAF : .NET 8.0.0 (42.42.42.42424), X64 RyuJIT AVX2
[2022/10/25 18:06:44][INFO]
[2022/10/25 18:06:44][INFO] PowerPlanMode=00000000-0000-0000-0000-000000000000 Toolchain=CoreRun IterationTime=250.0000 ms
[2022/10/25 18:06:44][INFO] MaxIterationCount=20 MinIterationCount=15 WarmupCount=1
[2022/10/25 18:06:44][INFO]
[2022/10/25 18:06:44][INFO] | Method | Options | Mean | Error | StdDev | Median | Min | Max | Allocated |
[2022/10/25 18:06:44][INFO] |---------------------------- |-------------------------- |-----------:|------------:|------------:|-----------:|---------:|-----------:|----------:|
[2022/10/25 18:06:44][INFO] | IsSuffix_DifferentLastChar | (, None, True) | 3,306.0 ns | 1,030.87 ns | 1,187.15 ns | 3,925.3 ns | 662.0 ns | 3,952.0 ns | - |
[2022/10/25 18:06:44][INFO] | IsPrefix_DifferentFirstChar | (en-US, IgnoreCase, True) | 538.3 ns | 10.12 ns | 11.24 ns | 542.3 ns | 501.9 ns | 545.7 ns | - |
[2022/10/25 18:06:44][INFO]
[2022/10/25 18:06:44][INFO] // * Hints *
[2022/10/25 18:06:44][INFO] Outliers
[2022/10/25 18:06:44][INFO] StringSearch.IsSuffix_DifferentLastChar: PowerPlanMode=00000000-0000-0000-0000-000000000000, Toolchain=CoreRun, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1 -> 3 outliers were detected (663.91 ns..686.64 ns)
[2022/10/25 18:06:44][INFO] StringSearch.IsPrefix_DifferentFirstChar: PowerPlanMode=00000000-0000-0000-0000-000000000000, Toolchain=CoreRun, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1 -> 2 outliers were detected (503.78 ns, 514.81 ns)
The issues from https://github.com/dotnet/perf-autofiling-issues/ repo resolved as duplicates look unrelated. They should be retrigged if they are real regressions.
Sorry about that -- the cross-linking the auto filing system is doing has changed recently and we struggling to make sense of things; seems like a fair number of unrelated things are getting lumped together.
@jkotas @EgorBo @AndyAyersMS this became clear it is not a globlaization/ICU issue. Any suggestion for who should look at this?
Side question, do we support building the runtime repo on Alpine? I am asking because I failed to build it. I am getting errors like:
CMake Error: CMake was unable to find a build program corresponding to "Unix Makefiles". CMAKE_MAKE_PROGRAM is not set. You probably need to select a different build tool.
CMake Error: CMAKE_C_COMPILER not set, after EnableLanguage
CMake Error: CMAKE_CXX_COMPILER not set, after EnableLanguage
@sblom 's team should look at this and provide access to the environment that reproduces the worst (up to 7x) regressions. I expect that we are going to find that this regression was caused by some kind of change in the environment setup.
I've created a branch internally forking off of commit 9b16818a which was the commit before the regression was introduced and ran the perf pipeline on it again just now using the current environment and I can't reproduce the regression, it is still showing a runtime of 656.2ns which is what it was before.
StringSearch.IsSuffix_DifferentLastChar: Job-ZFWQTY(PowerPlanMode=00000000-0000-0000-0000-000000000000, Toolchain=CoreRun, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1) [Options=(, None, True)] Runtime = .NET 8.0.0 (42.42.42.42424), X64 RyuJIT AVX2; GC = Concurrent Workstation Mean = 656.157 ns, StdErr = 1.859 ns (0.28%), N = 14, StdDev = 6.954 ns Min = 638.194 ns, Q1 = 653.613 ns, Median = 657.158 ns, Q3 = 661.107 ns, Max = 663.317 ns IQR = 7.494 ns, LowerFence = 642.371 ns, UpperFence = 672.348 ns ConfidenceInterval = [648.312 ns; 664.002 ns] (CI 99.9%), Margin = 7.845 ns (1.20% of Mean) Skewness = -1.08, Kurtosis = 3.52, MValue = 2 -------------------- Histogram -------------------- [634.407 ns ; 667.104 ns) | @@@@@@@@@@@@@@
This to me indicates that it's not caused by a change in the environment setup, but caused by changes between commit 9b16818a and commit 54b12a83. I will try run the pipeline on commits between these two versions to see if I can isolate which one might have caused the issue.
I ran the perf pipeline on commit c4341d45 which is a commit in between the two mentioned in the previous comment and I was able to reproduce the perf regression on it. The only other commits between 9b16818a and c4341d45 were definitely unrelated, so I think it is likely that the static linking GC PAL on linux commit is responsible for this regression somehow.
I've reached out to dnceng servies to see what I can do about getting access to a machine with the same/similar specs so I can collect some traces and we can better analyse the issue. Will update this issue when I have more information about that.
FYI @jkotas
Thanks @caaavik-msft. I changed the area label to GC.
For future investigations, do you have a constructions how we can run the test against different commits? I was trying to build the source on the Alpine container to run there but I couldn't build it.
Tagging subscribers to this area: @dotnet/gc See info in area-owners.md if you want to be subscribed.
Author: | performanceautofiler[bot] |
---|---|
Assignees: | - |
Labels: | `area-GC-coreclr`, `needs-author-action`, `Regression` |
Milestone: | Future |
Thanks @caaavik-msft. I changed the area label to GC.
For future investigations, do you have a constructions how we can run the test against different commits? I was trying to build the source on the Alpine container to run there but I couldn't build it.
The way I ran it is going to the internal version of the runtime repo in ADO, branching it at the commit I want to run the pipeline on, then editing the yaml files to make it only run the specific pipelines I care about, then you can run the dotnet-runtime-perf pipeline pointing to your branch.
I've gotten access to one of the alpine build machines we use for these benchmarks and am trying to get it built so I can run it and reproduce the regression but am running into some errors which I am trying to work out, once I have gotten it building though, will run PerfCollect to get the info we need to debug it.
Just an update on this issue, after getting access to a machine with the exact same specs as the build agent, I have been unable to reproduce this regression by running the benchmarks myself, even on the latest version of the runtime branch. I guess the way that the helix job runs things must be different than the way I am running them, but I am not sure why that might be. I'm going to get Drew to take a look at this when he returns from his leave to help with this further as he has a lot more experience in this area.
This issue has been automatically marked no-recent-activity
because it has not had any activity for 14 days. It will be closed if no further activity occurs within 14 more days. Any new comment (by anyone, not necessarily the author) will remove no-recent-activity
.
This issue has been automatically marked no-recent-activity
because it has not had any activity for 14 days. It will be closed if no further activity occurs within 14 more days. Any new comment (by anyone, not necessarily the author) will remove no-recent-activity
.
CC: @mangod9
Doesnt feel like this issue is actionable, @DrewScoggins ?
This got resolved in January.
Run Information
Regressions in System.Globalization.Tests.StringSearch
Test Report
Repro
Related Issues
Regressions
Improvements