Runtime: [Perf -23%] System.Collections.IndexerSet<String>.Span

[DrewScoggins]

I have added a new feature to the performance issues. If you click on the name of the benchmark in the table, you will be taken to a page that shows the entire test history for that benchmark.

Run Information

Architecture | x64
-- | --
OS | Windows 10.0.18362
Changes | diff

Regressions in System.Collections.IndexerSet

Benchmark | Baseline | Test | Test/Base | Modality | Baseline Outlier
-- | -- | -- | -- | -- | --
Span | 338.68 ns | 420.03 ns | 1.24 | | False

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.IndexerSet<String>*'

Histogram

System.Collections.IndexerSet.Span(Size: 512)

[333.353 ; 347.615) | @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
[347.615 ; 366.299) | @@@@@@@@@@@@@@
[366.299 ; 386.978) | @@@@@@@
[386.978 ; 401.231) | @@@@@
[401.231 ; 415.994) | 
[415.994 ; 430.257) | @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
[430.257 ; 443.483) | @

Docs

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

[msftbot[bot]]

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

[danmosemsft]

@DrewScoggins the diff link is bad again. It covers Aug 4-Aug 14th and won't open.

The correct link, based on zooming into the graph, is seems to be https://www.github.com/dotnet/runtime/compare/55ed5cda016f1dd3d730e81165c40d45327e1ba4...d1c7946bb0892005a58ec647e3a6d8f3514cdc6b

Is it possible to tighten the diff before opening such issues? Maybe a script needs adjustment, or it has to be done manually.

[DrewScoggins]

I updated it. This will likely always be a manual process, at least for the time being.

[danmosemsft]

Thank you. Can you pleaes also fix the typo in the repro instructions that I mentioned in an earlier issue? The Windows repro instructions should be like this I think

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

[danmosemsft]

Looking at the changes, there's no smoking gun but this one seems least unlikely to be relevant:

https://github.com/dotnet/runtime/commit/d1c7946bb0892005a58ec647e3a6d8f3514cdc6b https://github.com/dotnet/runtime/pull/40355

@trylek do you think that is possible?

Here is the test (parameterized for 'string'):
https://github.com/dotnet/performance/blob/8f00082e5f1ab8b86a98bf3bfc9c307a171912a3/src/benchmarks/micro/libraries/System.Collections/Indexer/IndexerSet.cs#L56-L62

[danmosemsft]

@trylek could you help us with the question above?

[trylek]

Thanks Dan for the heads-up. Well, I certainly cannot rule it out. While the change was intended exactly to fix perf issues observed in generic algorithms after Fadi's introduction of expanding dictionaries, I can theoretically imagine corner cases where the additional amount of runtime work upon dictionary expansion and / or the counterpart JIT change to stop treating the dictionary pointer as invariant (and eligible for common subexpression elimination) can actually cause a perf regression. I'll investigate it in more detail tomorrow, I'll diff the assembly with and without my change and I'll try to repro the perf difference locally; I'll continue updating this thread with my findings.

[danmosemsft]

Thank you @trylek

[trylek]

I have finally managed to make some progress on this regression even though I'm not completely done yet. I tested three possible causes of the regression - slightly increased allocation size of the generic dictionaries, the extra code for back-propagation of resolved dictionary slots and the JIT change; I believe that my local measurements confirm that the perf regression is due to the JIT aspect of my change.

As next step I would love to use COMPlus_JitDump to dump the two versions of the test method with and without my change and follow up with the JIT team to see whether we can mitigate this somehow; but I haven't yet figured out how to run a single test case once under corerun so that I can use the COMPlus variable; can someone here advise me how to do that?

In general, this is a tricky problem. My change was originally fixing a 5x regression from .NET Core 3.1 to .NET 5 caused by Fadi's expanding generic dictionaries that in turn were fixing other perf regressions in ASP.NET and elsewhere. The JIT dump can reveal chances for optimizations but I have no proof of that yet. I can easily continue owning this bug but I have a hard time to see anything I could do about it for .NET 5.

[danmosemsft]

@dotnet/jit-contrib can help with JitDump I expect.

With respect to 5.0 I think the most interesting thing would be to characterize how broad the impact might be in any other scenarios (?).

[AndyAyersMS]

@tyrek if you just want to see the code the jit generates then the -d option to the perf repo benchmark runner may get you what you need.

Or you can use the --corerun option to point things at a checked jit and specify COMPlus options to enable disassembly or umping. If you just want one run the -dry-run option may do the trick, but you probably don't want that as you won't see Tier1 codegen.

Alternatively you can extract the code into a standalone test and then run via a checked corerun -- typically if I do that I will disable tiered compilation to see code similar to what the Tier1 code would look like.

If the issue is that the dictionary lookup is no longer hoisted out of a loop (which one would suspect is the case) then there aren't any cheap/easy solutions. We could perhaps consider peeling the first loop iteration to do a pilot iteration and then hope that the dictionary state at that point captured the full behavior of the loop body, but it's not always going to be correct. Or we could do some conditional codegen in the loop itself to cache the dictionary after the first iteration or after every N iterations or something.

[danmosemsft]

I assumed "generic dictionaries" means a native datastructure in the CLR that is related to the type system (?) and is not directly related to "Dictionary" ?

[trylek]

@danmosemsft - Thanks for all the helpful feedback. Correct, "generic dictionaries" I referred to are an internal native CoreCLR detail around shared generics implementation, not directly related to System.Collections.Generic. The issue is that we're now marking the runtime dictionary as "non-invariant" (to make its possible expansion visible to the JITted code), causing JIT to generate slightly less optimized code when accessing it (typically loading it somewhat more often from memory as opposed to keeping it in a register within a method).

[trylek]

@AndyAyersMS - I have yet to grab the JIT dumps but I exactly suspect that dictionary access shortcuts within loops have the potential to regress other scenarios where minute details like inlining could previously cause fundamental perf differences due to the runtime code not discovering the expanded dictionary for the entire duration of the loop. I'll share the dumps as soon as I have them so that we can look in more detail, I still find it somewhat weird how a few more memory loads can bump up the duration of the test by something like 50~100 nanoseconds on my machine, that's just suspicious especially as the memory contents should converge quickly and remain in cache. The test seems to have exhibited pre-existing bimodal behavior that repro'es constantly for me with the running time fluctuating by about 30 nanoseconds, possibly due to some code / data layout detail causing cache aliasing or something.

[trylek]

OK, so the JIT logs for the method (with COMPlus_TieredCompilation=0) are here:

Fast version (before my change):

https://gist.github.com/trylek/eda36d83cce74bf55db5828721d9e848

Slow version (after my change):

https://gist.github.com/trylek/ee6512d53d25edab7591a5ea77dba585

As you can easily see, the only actual codegen diff is literally a single extra indirect mov from memory. Considering the memory address of the generic dictionary pointer (rbx in the "slow" case) doesn't change for the duration of the method (so that one would expect it to be covered by the processor cache), I tend to speculate that there must be something more at work to account for the 60 nanosecond difference like some cache aliasing. Taking that into account, 200 or so CPU cycles don't sound completely crazy w.r.t. a slow memory fetch against an invalidated cache entry; as I mentioned in my previous response, the test had pre-existing bimodal behavior fluctuating by about 30 nanoseconds - at the very least it seems to confirm that highly optimized code for this microbenchmark ends up with a pretty tight loop that is super sensitive to basically any changes.

[AndyAyersMS]

;; fast

G_M53660_IG06:        ; offs=000061H, size=0011H, bbWeight=2    PerfScore 5.50, gcrefRegs=00000040 {rsi}, byrefRegs=00000000 {}, byref

IN0014: 000061 mov      rdx, bword ptr [V12 rsp+28H]
IN0015: 000066 movsxd   rcx, eax
IN0016: 000069 xor      r8d, r8d
IN0017: 00006C mov      qword ptr [rdx+8*rcx], r8
IN0018: 000070 inc      eax

G_M53660_IG07:        ; offs=000072H, size=0007H, bbWeight=8    PerfScore 18.00, gcrefRegs=00000040 {rsi}, byrefRegs=00000000 {}, byref

IN0019: 000072 mov      rdx, rbx
IN001a: 000075 mov      rdx, qword ptr [rdx+8]

G_M53660_IG08:        ; offs=000079H, size=0006H, bbWeight=8    PerfScore 16.00, gcrefRegs=00000040 {rsi}, byrefRegs=00000000 {}, byref, isz

IN001b: 000079 cmp      eax, dword ptr [V13 rsp+30H]
IN001c: 00007D jl       SHORT G_M53660_IG06

;; slow

G_M53660_IG06:        ; offs=00005EH, size=0011H, bbWeight=2    PerfScore 5.50, gcrefRegs=00000040 {rsi}, byrefRegs=00000000 {}, byref

IN0013: 00005E mov      rdx, bword ptr [V12 rsp+28H]
IN0014: 000063 movsxd   rcx, eax
IN0015: 000066 xor      r8d, r8d
IN0016: 000069 mov      qword ptr [rdx+8*rcx], r8
IN0017: 00006D inc      eax

G_M53660_IG07:        ; offs=00006FH, size=0007H, bbWeight=8    PerfScore 32.00, gcrefRegs=00000040 {rsi}, byrefRegs=00000000 {}, byref

IN0018: 00006F mov      rdx, qword ptr [rbx]
IN0019: 000072 mov      rdx, qword ptr [rdx+8]

G_M53660_IG08:        ; offs=000076H, size=0006H, bbWeight=8    PerfScore 16.00, gcrefRegs=00000040 {rsi}, byrefRegs=00000000 {}, byref, isz

IN001a: 000076 cmp      eax, dword ptr [V13 rsp+30H]
IN001b: 00007A jl       SHORT G_M53660_IG06

Oddly it looks like the dictionary lookup is entirely dead in both loops, which might explain the outsized cost -- there isn't much going on besides this. Are we not marking those loads as non-faulting? Let me look a bit deeper...

[AndyAyersMS]

Seems to be the case:

            [000072] --C-G-------              \--*  CALL help long   HELPER.CORINFO_HELP_RUNTIMEHANDLE_CLASS
            [000074] ------------ arg0            +--*  EQ        int
            [000070] n-----------                 |  +--*  IND       long
            [000069] ------------                 |  |  \--*  ADD       long
            [000066] ------------                 |  |     +--*  LCL_VAR   long   V10 tmp6
            [000068] ------------                 |  |     \--*  CNS_INT   long   96
            [000073] ------------                 |  \--*  CNS_INT   long   0
            [000083] ------------ arg1            +--*  LE        int
            [000081] ------------                 |  +--*  IND       long               // should be nonfaulting
            [000080] ------------                 |  |  \--*  ADD       long
            [000067] ------------                 |  |     +--*  LCL_VAR   long   V10 tmp6
            [000079] ------------                 |  |     \--*  CNS_INT   long   8
            [000082] ------------                 |  \--*  CNS_INT   long   96
            [000075] n----------- arg2            +--*  IND       long
            [000076] ------------                 |  \--*  ADD       long
            [000077] ------------                 |     +--*  LCL_VAR   long   V10 tmp6
            [000078] ------------                 |     \--*  CNS_INT   long   96
            [000058] ------------ arg3            +--*  LCL_VAR   long   V09 tmp5
            [000071] ------------ arg4            \--*  CNS_INT(h) long   0x7ff9f1337fe8 token

Note we have 3 identical IND trees, the middle one is not marked as GTF_IND_NONFAULTING (no n) flag.

cc @sandreenko

[trylek]

Sounds great, thanks Andy for following up so quickly. For now I understand your response and explanation so that my change basically just uncovered a pre-existing limitation due to which JIT sometimes holds on to bits of dead code around generic lookup in the produced codegen; please let me know if you think I can be of more help in investigating this issue.

[AndyAyersMS]

my change basically just uncovered a pre-existing limitation

I think so, yes...

I was thinking we might be able to see a regression on this test from when the dictionary changes first went in (2/24, then reverted 3/6, then un-reverted 3/9), but we only have perf data from the start of March, and if anything it looks like those changes may have helped this test somewhat (slight regression perhaps from 3/7-3/9). So might be worth comparing vs 3.1 too.

The fix should be simple enough...

[sandreenko]

Not sure where we create this ind, is it in GenTree* Compiler::impRuntimeLookupToTree?

[AndyAyersMS]

Yes, in impRuntimeLookupToTree, it is the sizeValue tree.

[sandreenko]

I will prepare a PR based on Andy's proposed fix.