[Perf] Windows/x64: 3 Regressions on 6/3/2024 10:30:18 PM

[performanceautofiler]

Run Information

Name	Value
Architecture	x64
OS	Windows 10.0.22631
Queue	ViperWindows
Baseline	c6bfb06e23458e583c46cb2162c827acc8dd2f35
Compare	9a3d45a66d96dd73b360471e0de8f0c5fb7c89c0
Diff	Diff
Configs	CompilationMode:tiered, RunKind:micro

Regressions in System.IO.Tests.StringReaderReadLineTests

Benchmark	Baseline	Test	Test/Base	Test Quality	Edge Detector	Baseline IR	Compare IR	IR Ratio
ReadLineAsync - Duration of single invocation 📝 - Benchmark Source ADX - Test Multi Config Graph	53.30 μs	65.99 μs	1.24	0.42	False
ReadLine - Duration of single invocation 📝 - Benchmark Source ADX - Test Multi Config Graph	9.93 μs	10.73 μs	1.08	0.09	False
ReadLine - Duration of single invocation 📝 - Benchmark Source ADX - Test Multi Config Graph	65.66 μs	72.42 μs	1.10	0.00	False

Test Report

Repro

General Docs link: https://github.com/dotnet/performance/blob/main/docs/benchmarking-workflow-dotnet-runtime.md

git clone https://github.com/dotnet/performance.git
py .\performance\scripts\benchmarks_ci.py -f net8.0 --filter 'System.IO.Tests.StringReaderReadLineTests*'

System.IO.Tests.StringReaderReadLineTests.ReadLineAsync(LineLengthRange: [ 1, 8])

ETL Files

Histogram

JIT Disasms

System.IO.Tests.StringReaderReadLineTests.ReadLine(LineLengthRange: [ 9, 32])

ETL Files

Histogram

JIT Disasms

System.IO.Tests.StringReaderReadLineTests.ReadLine(LineLengthRange: [ 1, 1])

ETL Files

Histogram

JIT Disasms

Docs

Profiling workflow for dotnet/runtime repository
Benchmarking workflow for dotnet/runtime repository

[LoopedBard3]

Commit range: 2a80808...1e0c243

Slightly suspect this PR: #101020

[dotnet-policy-service]

Tagging subscribers to this area: @dotnet/area-system-io
See info in area-owners.md if you want to be subscribed.

[LoopedBard3]

Other potentially related regressions:
Windows x64: dotnet/perf-autofiling-issues#36066, dotnet/perf-autofiling-issues#36074

Linux x64: dotnet/perf-autofiling-issues#36053

[adamsitnik]

Moving to area-System.Runtime since it seems to be related to the recent StringBuilder changes

[stephentoub]

Moving to area-System.Runtime since it seems to be related to the recent StringBuilder changes

@adamsitnik, which changes? I'm missing it in the diff.

[adamsitnik]

@adamsitnik, which changes? I'm missing it in the diff.

I relied on this comment: #103296 (comment)

[stephentoub]

Interesting... that's not the same as the diff link at the top of the post: c6bfb06...9a3d45a

[stephentoub]

It's also suspect that a commit which just changed length = Math.Min(m_ChunkChars.Length - m_ChunkLength, count); to length = count; when count was guaranteed to be the min, anyway, would have that kind of negative impact.

[jozkee]

Commit range: 2a80808...1e0c243

@LoopedBard3 where did you get that range from? Which one is the correct one, yours or c6bfb06...9a3d45a (the one next to Diff)?

[LoopedBard3]

I grabbed that range manually using the graph in the [1, 1] ReadLine test history link as it had the clearest regression point for comparison. Looking at the [9, 32] Readline history, there may be something also around the diff range next to Diff. Part of the reason for this difference is that the autofiling tool is making a best effort for both linking issues together by commit time and in figuring out the commits to blame. There is also a minor regression in the listed commit range it seems for the [1, 1] ReadLine test history but it immediately went back to the expected result.

[jozkee]

After a long git bisect, c95d3b8 seems to be culprit cc @mangod9 @janvorli @eduardo-vp @jkotas

| Method        | Job        | OutlierMode | Toolchain   | MemoryRandomization | LineLengthRange | Mean      | Error     | StdDev    | Median    | Min       | Max       | Ratio | RatioSD | Gen0    | Allocated | Alloc Ratio |
|-------------- |----------- |------------ |------------ |-------------------- |---------------- |----------:|----------:|----------:|----------:|----------:|----------:|------:|--------:|--------:|----------:|------------:|
| ReadLine      | Job-UEOZUI | Default     | main+revert | Default             | [   1,    1]    | 41.888 μs | 0.3827 μs | 0.3392 μs | 41.945 μs | 41.394 μs | 42.563 μs |  0.85 |    0.01 |  7.7100 | 128.05 KB |        1.00 |
| ReadLine      | Job-PKFCUA | Default     | main        | Default             | [   1,    1]    | 49.311 μs | 0.5177 μs | 0.4842 μs | 49.128 μs | 48.809 μs | 50.527 μs |  1.00 |    0.01 |  7.7381 | 128.05 KB |        1.00 |
|               |            |             |             |                     |                 |           |           |           |           |           |           |       |         |         |           |             |
| ReadLine      | Job-UEOZUI | Default     | main+revert | Default             | [   1,    8]    | 27.023 μs | 1.6694 μs | 1.9224 μs | 27.321 μs | 23.540 μs | 29.622 μs |  0.98 |    0.10 |  5.3571 |  88.81 KB |        1.00 |
| ReadLine      | Job-PKFCUA | Default     | main        | Default             | [   1,    8]    | 27.614 μs | 1.8414 μs | 2.1206 μs | 27.066 μs | 25.370 μs | 31.818 μs |  1.01 |    0.10 |  5.3514 |  88.81 KB |        1.00 |
|               |            |             |             |                     |                 |           |           |           |           |           |           |       |         |         |           |             |
| ReadLine      | Job-UEOZUI | Default     | main+revert | Default             | [   9,   32]    |  7.474 μs | 0.6861 μs | 0.7901 μs |  7.473 μs |  6.280 μs |  8.959 μs |  1.02 |    0.11 |  2.8788 |  47.16 KB |        1.00 |
| ReadLine      | Job-PKFCUA | Default     | main        | Default             | [   9,   32]    |  7.299 μs | 0.0644 μs | 0.0503 μs |  7.290 μs |  7.236 μs |  7.397 μs |  1.00 |    0.01 |  2.8736 |  47.16 KB |        1.00 |
|               |            |             |             |                     |                 |           |           |           |           |           |           |       |         |         |           |             |
| ReadLineAsync | Job-NZIKZL | DontRemove  | main+revert | True                | [   1,    1]    | 70.552 μs | 0.5119 μs | 0.4788 μs | 70.676 μs | 69.716 μs | 71.302 μs |  0.79 |    0.01 | 31.2500 | 512.09 KB |        1.00 |
| ReadLineAsync | Job-ABBFHP | DontRemove  | main        | True                | [   1,    1]    | 88.924 μs | 0.6729 μs | 0.6294 μs | 89.129 μs | 88.125 μs | 90.059 μs |  1.00 |    0.01 | 31.2500 | 512.09 KB |        1.00 |
|               |            |             |             |                     |                 |           |           |           |           |           |           |       |         |         |           |             |
| ReadLineAsync | Job-NZIKZL | DontRemove  | main+revert | True                | [   1,    8]    | 47.085 μs | 0.6522 μs | 0.6101 μs | 47.089 μs | 46.104 μs | 48.302 μs |  0.86 |    0.03 | 17.1131 | 282.59 KB |        1.00 |
| ReadLineAsync | Job-ABBFHP | DontRemove  | main        | True                | [   1,    8]    | 54.812 μs | 1.3963 μs | 1.6080 μs | 54.421 μs | 52.727 μs | 57.808 μs |  1.00 |    0.04 | 17.1405 | 282.59 KB |        1.00 |
|               |            |             |             |                     |                 |           |           |           |           |           |           |       |         |         |           |             |
| ReadLineAsync | Job-NZIKZL | DontRemove  | main+revert | True                | [   9,   32]    | 12.663 μs | 0.4118 μs | 0.4742 μs | 12.542 μs | 12.148 μs | 13.841 μs |  0.95 |    0.04 |  6.0218 |  98.63 KB |        1.00 |
| ReadLineAsync | Job-ABBFHP | DontRemove  | main        | True                | [   9,   32]    | 13.395 μs | 0.2738 μs | 0.3153 μs | 13.339 μs | 12.969 μs | 14.345 μs |  1.00 |    0.03 |  5.9961 |  98.63 KB |        1.00 |

[mangod9]

some of these microbenchmark regressions are expected with CET enabled as discussed here: #103654

[jozkee]

Comparing c286a8e (commit older than any visible regression) versus main+revert of c95d3b8:

| Method        | Job        | OutlierMode | Toolchain    | MemoryRandomization | LineLengthRange | Mean      | Error     | StdDev    | Median    | Min       | Max       | Ratio | RatioSD | Gen0    | Allocated | Alloc Ratio |
|-------------- |----------- |------------ |------------- |-------------------- |---------------- |----------:|----------:|----------:|----------:|----------:|----------:|------:|--------:|--------:|----------:|------------:|
| ReadLine      | Job-CJBAKZ | Default     | c286a8e      | Default             | [   1,    1]    | 41.167 μs | 0.2643 μs | 0.2473 μs | 41.088 μs | 40.866 μs | 41.696 μs |  1.00 |    0.01 |  7.8329 | 128.05 KB |        1.00 |
| ReadLine      | Job-DYGSFH | Default     | main+revert  | Default             | [   1,    1]    | 40.789 μs | 0.1925 μs | 0.1607 μs | 40.748 μs | 40.543 μs | 41.149 μs |  0.99 |    0.01 |  7.8125 | 128.05 KB |        1.00 |
|               |            |             |              |                     |                 |           |           |           |           |           |           |       |         |         |           |             |
| ReadLine      | Job-CJBAKZ | Default     | c286a8e      | Default             | [   1,    8]    | 27.831 μs | 0.6285 μs | 0.7238 μs | 27.911 μs | 26.713 μs | 29.080 μs |  1.00 |    0.04 |  5.4250 |  88.81 KB |        1.00 |
| ReadLine      | Job-DYGSFH | Default     | main+revert  | Default             | [   1,    8]    | 25.535 μs | 1.8208 μs | 2.0968 μs | 24.145 μs | 23.692 μs | 29.300 μs |  0.92 |    0.08 |  5.3914 |  88.81 KB |        1.00 |
|               |            |             |              |                     |                 |           |           |           |           |           |           |       |         |         |           |             |
| ReadLine      | Job-CJBAKZ | Default     | c286a8e      | Default             | [   9,   32]    |  6.802 μs | 0.2152 μs | 0.2479 μs |  6.836 μs |  6.380 μs |  7.241 μs |  1.00 |    0.05 |  2.8739 |  47.16 KB |        1.00 |
| ReadLine      | Job-DYGSFH | Default     | main+revert  | Default             | [   9,   32]    |  6.746 μs | 0.4950 μs | 0.5501 μs |  6.435 μs |  6.258 μs |  7.823 μs |  0.99 |    0.09 |  2.8854 |  47.16 KB |        1.00 |
|               |            |             |              |                     |                 |           |           |           |           |           |           |       |         |         |           |             |
| ReadLineAsync | Job-XMRSJL | DontRemove  | c286a8e      | True                | [   1,    1]    | 71.412 μs | 0.8508 μs | 0.7958 μs | 71.130 μs | 70.446 μs | 73.153 μs |  1.00 |    0.02 | 31.1086 | 512.09 KB |        1.00 |
| ReadLineAsync | Job-AQLCAY | DontRemove  | main+revert  | True                | [   1,    1]    | 69.474 μs | 0.3548 μs | 0.3319 μs | 69.450 μs | 68.984 μs | 70.228 μs |  0.97 |    0.01 | 31.2500 | 512.09 KB |        1.00 |
|               |            |             |              |                     |                 |           |           |           |           |           |           |       |         |         |           |             |
| ReadLineAsync | Job-XMRSJL | DontRemove  | c286a8e      | True                | [   1,    8]    | 47.671 μs | 0.2992 μs | 0.2799 μs | 47.718 μs | 47.289 μs | 48.249 μs |  1.00 |    0.01 | 17.1131 | 282.59 KB |        1.00 |
| ReadLineAsync | Job-AQLCAY | DontRemove  | main+revert  | True                | [   1,    8]    | 47.060 μs | 0.3772 μs | 0.3529 μs | 47.128 μs | 46.089 μs | 47.767 μs |  0.99 |    0.01 | 17.1642 | 282.59 KB |        1.00 |
|               |            |             |              |                     |                 |           |           |           |           |           |           |       |         |         |           |             |
| ReadLineAsync | Job-XMRSJL | DontRemove  | c286a8e      | True                | [   9,   32]    | 11.678 μs | 0.3742 μs | 0.4309 μs | 11.434 μs | 11.345 μs | 12.525 μs |  1.00 |    0.05 |  6.0208 |  98.63 KB |        1.00 |
| ReadLineAsync | Job-AQLCAY | DontRemove  | main+revert  | True                | [   9,   32]    | 11.722 μs | 0.4592 μs | 0.5288 μs | 11.556 μs | 10.960 μs | 12.689 μs |  1.01 |    0.06 |  6.0326 |  98.63 KB |        1.00 |

Looks like c95d3b8 is the only significant regression. Closing.