[Perf] Regression in System.Collections.CtorFromCollection<String>.ConcurrentQueue

[DrewScoggins]

Run Information

Architecture	x64
OS	Windows 10.0.18362
Baseline	07336810acf3b4e7bdd0fb7da87b54920ea9c382
Compare	405da674b633a99cc41be9e18c2e4d84b1b01639
Diff	Diff

Regressions in System.Collections.CtorFromCollection<String>

Benchmark	Baseline	Test	Test/Base	Test Quality	Edge Detector	Baseline IR	Compare IR	IR Ratio	Baseline ETL	Compare ETL
ConcurrentQueue - Duration of single invocation	7.75 μs	8.35 μs	1.08	0.00	True

Historical Data in Reporting System

Repro

git clone https://github.com/dotnet/performance.git
py .\performance\scripts\benchmarks_ci.py -f netcoreapp5.0 --filter 'System.Collections.CtorFromCollection<String>*'

Payloads

Baseline
Compare

Histogram

System.Collections.CtorFromCollection<String>.LinkedList(Size: 512)

System.Collections.CtorFromCollection<String>.ConcurrentQueue(Size: 512)

Docs

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

Tagging subscribers to this area: @eiriktsarpalis
See info in area-owners.md if you want to be subscribed.

Issue Details

---

Run Information

Architecture	x64
OS	Windows 10.0.18362
Baseline	07336810acf3b4e7bdd0fb7da87b54920ea9c382
Compare	405da674b633a99cc41be9e18c2e4d84b1b01639
Diff	Diff

Regressions in System.Collections.CtorFromCollection<String>

Benchmark	Baseline	Test	Test/Base	Test Quality	Edge Detector	Baseline IR	Compare IR	IR Ratio	Baseline ETL	Compare ETL
ConcurrentQueue - Duration of single invocation	7.75 μs	8.35 μs	1.08	0.00	True

Historical Data in Reporting System

Repro

git clone https://github.com/dotnet/performance.git
py .\performance\scripts\benchmarks_ci.py -f netcoreapp5.0 --filter 'System.Collections.CtorFromCollection<String>*'

Payloads

Baseline
Compare

Histogram

System.Collections.CtorFromCollection<String>.LinkedList(Size: 512)

System.Collections.CtorFromCollection<String>.ConcurrentQueue(Size: 512)

Docs

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

Author:	DrewScoggins
Assignees:	-
Labels:	arch-x64, area-System.Collections, os-windows, tenet-performance, tenet-performance-benchmarks, untriaged
Milestone:	-

[danmoseley]

There were no changes to S.C.C in this interval and nothing jumps out of the other libraries history (I would assume this test uses not much else)

This is labeled x64 meaning it didn't regress on other arch. Falling back to codegen, I see these:

C:\git\runtime\src\coreclr>git lg ede3733b1cf5902899e56caf748492ed993c98c8...efd0bb58bdc2d7591d77e604b810c096a7a5d58e -- **
* f57b6e7308e - Add crash report to createdump for Linux Watson  (#55438) (2 weeks ago) <Mike McLaughlin>
* a4590197c10 - Use init rather than ms extension syntax (#55475) (2 weeks ago) <Adeel Mujahid>
* 6a47ecf4a8e - W^X support (#54954) (2 weeks ago) <Jan Vorlicek>
* fce412be777 - Support filtering ObjectAllocated callback for pinned object heap allocation only (#55448) (2 weeks ago) <Yauk>
* 02ccdacb069 - Improve loop cloning, with debugging improvements (#55299) (2 weeks ago) <Bruce Forstall>
* 65b472a0f31 - Handle a missing case in zero-extend peephole (#55129) (2 weeks ago) <Jakob Botsch Nielsen>
* 27b564ab965 - Spill single-def variable at definition to avoid further spilling (#54345) (2 weeks ago) <Kunal Pathak>
* 0f5a39df193 - [Mono] Add Mono Profiler events into EventPipe. (#55264) (2 weeks ago) <Johan Lorensson>
* 39d1161c889 - Fix helloworld on x86 Linux (#55095) (2 weeks ago) <t-mustafin>
* c8486b69ced - Remove some left-over debug code (#55408) (2 weeks ago) <Jakob Botsch Nielsen>
* 43cdfa10ac6 - Fix GCMemoryInfo.TotalAvailableMemoryBytes under Wow (#55387) (2 weeks ago) <Jan Kotas>

The test loops over 512 strings, adding each to a queue segment. there is no contention so I'm not sure there is much nested looping though.

@BruceForstall is it possible something like #55299 could have affected this?

[BruceForstall]

#55299 could be the cause if (1) there's a tight, commonly-executed loop, (2) the JIT's loop cloning kicked in (this happens for loops that look like "for (int i = 0; i < n; i++)") and there's an array access using the loop variable, e.g., "a[i]", where it knows it can get rid of the array bounds check, and (3) there's some other conditional branch in the loop. Then, it's possible that a change is code alignment causes the Intel jcc erratum to kick in.

#54345 is another possibility. cc @kunalspathak

[kunalspathak]

I reverted each of below commits and generated disassembly of entire benchmark run but didn't see anything that comes out:

* 02ccdacb069 - Improve loop cloning, with debugging improvements (#55299) (2 weeks ago) <Bruce Forstall>
* 65b472a0f31 - Handle a missing case in zero-extend peephole (#55129) (2 weeks ago) <Jakob Botsch Nielsen>
* 27b564ab965 - Spill single-def variable at definition to avoid further spilling (#54345) (2 weeks ago) <Kunal Pathak>

VTune points at TryEnqueue method being hottest.

Further digging shows that cmp is the hottest instruction.

I tried looking at disassembly difference before and after LSRA changes in #54345 and the only thing that comes out is before LSRA change, we would spill the value into [rsp+2CH] few instructions before using that value in cmp eax, [rsp+2CH]. After LSRA change, the mov has moved at the top of the block and I am guessing there might be some data caching involved which is not applicable after my change?

[eiriktsarpalis]

I'm not able to discern a regression running the particular benchmark on my machine. Here are the results of a few runs:

0733681 (baseline)

Method	Size	Mean	Error	StdDev	Median	Min	Max	Gen 0	Gen 1	Gen 2	Allocated
ConcurrentQueue	512	6.021 us	0.0779 us	0.0691 us	5.998 us	5.941 us	6.180 us	0.8383	0.0493	-	8 KB
ConcurrentQueue	512	6.527 us	0.4597 us	0.5294 us	6.416 us	6.040 us	7.538 us	0.8380	0.0270	-	8 KB
ConcurrentQueue	512	6.287 us	0.1688 us	0.1876 us	6.213 us	6.058 us	6.695 us	0.8272	0.0487	-	8 KB
ConcurrentQueue	512	6.004 us	0.0181 us	0.0160 us	5.997 us	5.984 us	6.036 us	0.8410	0.0481	-	8 KB
ConcurrentQueue	512	6.400 us	0.3274 us	0.3770 us	6.404 us	5.967 us	7.328 us	0.8333	0.0476	-	8 KB
ConcurrentQueue	512	5.990 us	0.0215 us	0.0168 us	5.984 us	5.972 us	6.032 us	0.8307	0.0489	-	8 KB
ConcurrentQueue	512	6.360 us	0.3821 us	0.4400 us	6.037 us	5.969 us	7.261 us	0.8340	0.0477	-	8 KB
ConcurrentQueue	512	5.967 us	0.0190 us	0.0158 us	5.959 us	5.945 us	5.995 us	0.8301	0.0268	-	8 KB
ConcurrentQueue	512	6.329 us	0.4166 us	0.4797 us	6.014 us	5.926 us	7.704 us	0.8323	0.0268	-	8 KB

405da67 (compare)

Method	Size	Mean	Error	StdDev	Median	Min	Max	Gen 0	Gen 1	Gen 2	Allocated
ConcurrentQueue	512	6.039 us	0.0432 us	0.0337 us	6.038 us	5.992 us	6.104 us	0.8443	0.0482	-	8 KB
ConcurrentQueue	512	5.986 us	0.0231 us	0.0205 us	5.987 us	5.950 us	6.024 us	0.8482	0.0485	-	8 KB
ConcurrentQueue	512	5.994 us	0.0361 us	0.0282 us	5.987 us	5.964 us	6.073 us	0.8426	0.0482	-	8 KB
ConcurrentQueue	512	6.066 us	0.0991 us	0.0927 us	6.031 us	5.984 us	6.311 us	0.8337	0.0253	-	8 KB
ConcurrentQueue	512	6.348 us	0.3685 us	0.4244 us	6.210 us	5.944 us	7.202 us	0.8352	0.0477	-	8 KB
ConcurrentQueue	512	6.325 us	0.3304 us	0.3805 us	6.252 us	5.913 us	6.843 us	0.8340	0.0477	-	8 KB
ConcurrentQueue	512	6.305 us	0.3562 us	0.3959 us	6.250 us	5.929 us	6.951 us	0.8346	0.0477	-	8 KB
ConcurrentQueue	512	5.951 us	0.0275 us	0.0230 us	5.951 us	5.922 us	5.990 us	0.8324	0.0476	-	8 KB
ConcurrentQueue	512	5.930 us	0.0225 us	0.0188 us	5.933 us	5.904 us	5.974 us	0.8311	0.0475	-	8 KB
ConcurrentQueue	512	5.973 us	0.0109 us	0.0091 us	5.970 us	5.961 us	5.990 us	0.8433	0.0482	-	8 KB
ConcurrentQueue	512	6.332 us	0.3394 us	0.3909 us	6.078 us	5.974 us	7.293 us	0.8410	0.0481	-	8 KB

Running statistical tests comparing the two commits with 3% threshold also show no perf regression.