System.Collections.Immutable.ImmutableList1+Enumerator[System.Collections.Generic.KeyValuePair2[System.__Canon,System.__Canon]].Dispose() takes 17 ms to JIT

[davkean]

Looking at some perf problems with MSBuild, we're spending lots of time JITing, this one in particular stood out:

JitTime (msec)	ILSize	NativeSize	Method	BG	Module
17.4	74	163	System.Collections.Immutable.ImmutableList1+Enumerator[System.Collections.Generic.KeyValuePair2[System.__Canon,System.__Canon]].Dispose()	JIT	System.Collections.Immutable.dll

Almost all other methods are under 1ms. Can we simplify this method?

[benaadams]

Method for reference

https://github.com/dotnet/corefx/blob/1fe52f7ff4e29462f75da9ae1c35d9789ad13709/src/System.Collections.Immutable/src/System/Collections/Immutable/ImmutableList_1.Enumerator.cs#L150-L162

[davkean]

Oh that inline reference is nice.

[benaadams]

Doesn't do the inline reference in coreclr; I had to copy and paste code; like an animal...

[davkean]

That's it, this feature is useless to me. Turn it off @github! :)

[davkean]

Make note that we've NGEN'd Immutable - so these are methods being JIT'd above and beyond what's NGEN'd.

In this trace, it took a total of 35ms to JIT immutable in the following:

Start (msec)	JitTimemsec	IL Size	Native Size	Method Name	BG	Module
3,038.615	1.6	12	54	System.Collections.Immutable.ImmutableDictionary.CreateBuilder(class System.Collections.Generic.IEqualityComparer`1)	JIT	System.Collections.Immutable.dll
3,040.210	0.2	12	58	System.Collections.Immutable.ImmutableDictionary.Create(class System.Collections.Generic.IEqualityComparer`1)	JIT	System.Collections.Immutable.dll
3,040.506	0.1	11	58	System.Collections.Immutable.ImmutableDictionary`2+<>c[System.__Canon,System.__Canon]..cctor()	JIT	System.Collections.Immutable.dll
3,040.600	0.0	7	1	System.Collections.Immutable.ImmutableDictionary`2+<>c[System.__Canon,System.__Canon]..ctor()	JIT	System.Collections.Immutable.dll
3,040.741	30.5	74	163	System.Collections.Immutable.ImmutableList1+Enumerator[System.Collections.Generic.KeyValuePair2[System.__Canon,System.__Canon]].Dispose()	JIT	System.Collections.Immutable.dll
3,071.485	0.1	12	40	System.Collections.Immutable.ImmutableList`1[System.__Canon].System.Collections.IEnumerable.GetEnumerator()	JIT	System.Collections.Immutable.dll
3,071.662	0.2	63	227	System.Collections.Immutable.AllocFreeConcurrentStack`1[System.__Canon].get_ThreadLocalStack()	JIT	System.Collections.Immutable.dll
3,071.937	0.1	16	98	System.Collections.Immutable.AllocFreeConcurrentStack`1[System.__Canon]..cctor()	JIT	System.Collections.Immutable.dll
3,072.046	0.1	45	63	System.Collections.Generic.Stack1[System.Collections.Immutable.RefAsValueType1[System.__Canon]]..ctor(int32)	JIT	System.dll
3,072.188	0.2	115	131	System.Collections.Generic.Stack1[System.Collections.Immutable.RefAsValueType1[System.__Canon]].Push(!0)	JIT	System.dll
3,072.404	0.1	86	80	System.Collections.Generic.Stack1[System.Collections.Immutable.RefAsValueType1[System.__Canon]].Pop()	JIT	System.dll
3,072.558	0.1	12	16	System.Collections.Immutable.ImmutableList`1+Enumerator[System.__Canon].System.Collections.IEnumerator.get_Current()	JIT	System.Collections.Immutable.dll
3,072.686	0.2	30	96	System.Collections.Immutable.ImmutableList1+Builder[System.__Canon].AddRange(class System.Collections.Generic.IEnumerable1)	JIT	System.Collections.Immutable.dll
3,074.201	0.1	11	58	System.Collections.Immutable.ImmutableList1+Node[System.Collections.Generic.KeyValuePair2[System.__Canon,System.__Canon]]..cctor()	JIT	System.Collections.Immutable.dll
3,074.272	0.0	14	5	System.Collections.Immutable.ImmutableList1+Node[System.Collections.Generic.KeyValuePair2[System.__Canon,System.__Canon]]..ctor()	JIT	System.Collections.Immutable.dll
3,074.337	0.1	9	64	System.Collections.Immutable.Requires.NotNullPassthrough(!!0,class System.String)	JIT	System.Collections.Immutable.dll
3,074.492	0.3	16	59	System.Collections.Immutable.ImmutableDictionary2+<>c[System.__Canon,System.__Canon].<.cctor>b__107_0(value class System.Collections.Generic.KeyValuePair2>)	JIT	System.Collections.Immutable.dll
3,074.855	0.1	38	39	System.Collections.Immutable.ImmutableList1+Node[System.Collections.Generic.KeyValuePair2[System.__Canon,System.__Canon]].Freeze()	JIT	System.Collections.Immutable.dll
3,078.095	0.1	11	58	System.Collections.Immutable.ImmutableHashSet`1+<>c[System.__Canon]..cctor()	JIT	System.Collections.Immutable.dll
3,078.185	0.0	7	1	System.Collections.Immutable.ImmutableHashSet`1+<>c[System.__Canon]..ctor()	JIT	System.Collections.Immutable.dll
3,078.567	0.2	12	44	System.Collections.Immutable.ImmutableList`1+Builder[System.__Canon].System.Collections.Generic.IEnumerable.GetEnumerator()	JIT	System.Collections.Immutable.dll
3,078.828	0.1	11	130	System.Collections.Immutable.ImmutableList`1+Node[System.__Canon].GetEnumerator(class Builder)	JIT	System.Collections.Immutable.dll
3,079.757	0.3	16	24	System.Collections.Immutable.ImmutableHashSet1+<>c[System.__Canon].<.cctor>b__85_0(value class System.Collections.Generic.KeyValuePair2>)	JIT	System.Collections.Immutable.dll
3,084.137	0.2	18	99	System.Collections.Immutable.ImmutableList1+Builder[Microsoft.Build.Evaluation.LazyItemEvaluator4+ItemData[System.__Canon,System.__Canon,System.__Canon,System.__Canon]].IndexOf(!0)	JIT	System.Collections.Immutable.dll
3,085.044	0.4	166	419	System.Collections.Immutable.ImmutableList1+Node[Microsoft.Build.Evaluation.LazyItemEvaluator4+ItemData[System.__Canon,System.__Canon,System.__Canon,System.__Canon]].IndexOf(!0,int32,int32,class System.Collections.Generic.IEqualityComparer`1)	JIT	System.Collections.Immutable.dll
3,085.643	0.5	310	227	System.Collections.Immutable.ImmutableList1+Node[Microsoft.Build.Evaluation.LazyItemEvaluator4+ItemData[System.__Canon,System.__Canon,System.__Canon,System.__Canon]].RemoveAt(int32)	JIT	System.Collections.Immutable.dll

[karelz]

@davkean did you try to reproduce it by directly using this method and NGen'ing?
That would help us isolate the issue ...

cc @mellinoe

[davkean]

@karelz Not sure I understand what you mean.

[benaadams]

Seeing if I can get a Jit output. Do you know what the type is?

There is some wild generic use :)

ImmutableList<LazyItemEvaluator<P, I, M, D>.ItemData>.Enumerator

But can't find a ImmutableList where it gets a KeyValuePair

[benaadams]

nvm, am following instructions in other issue

[karelz]

@davkean I meant isolated repro to confirm the 30.5ms of JIT time for System.Collections.Immutable.ImmutableList1+Enumerator[System.Collections.Generic.KeyValuePair2[System.__Canon,System.__Canon]].Dispose()

[AndyAyersMS]

If you have ETL lying around, send it my way. Likely there is a classload or something similar in there, but best to be sure.

Also you are presumably prejitting in R2R format, right? R2R can't handle all the cases that classic ngen can, so some extra jitting is expected over what you might have seen on desktop.

[davkean]

We're not using R2R (didn't even know it was enabled for desktop?) - we're using classic NGEN.

Interestingly enough when I was looking at this, I could repro this over and over again, if I try to repro it now, it's still taking a while (4ms) but not as long as before. Might have had an OS update in between?

I've got a trace where we took 30ms to jit it, available: \mlangfs1\public\davkean\corefx\23125 (uploading now, should take 20 minutes).

[davkean]

My repro was this:

1. Clone http://github.com/dotnet/roslyn
2. Checkout e7869bdaa642214a142d27e6a77263e0e3ba1a66
3. Open Visual Studio Command Prompt
4. Run Restore.cmd
5. msbuild /nologo /m:1 /v:m /clp:Summary;PerformanceSummary /flp:v:d /t:ReportAssetsLogMessages /p:"SolutionFileName=Roslyn.sln;LangName=en-US;Configuration=Debug;LangID=1033;DesignTimeBuild=true;SolutionDir=E:\\roslyn\\;SolutionExt=.sln;BuildingInsideVisualStudio=true;DefineExplicitDefaults=true;Platform=AnyCPU;SolutionPath=E:\\roslyn\\Roslyn.sln;SolutionName=Roslyn;DevEnvDir=C:\Program Files (x86)\Microsoft Visual Studio\Enterprise\Common7\IDE;BuildingProject=false" E:\roslyn\src\Compilers\VisualBasic\VbcCore\VbcCore.csproj

[AndyAyersMS]

From the ETL, jitting for that method started at 3.040741s and ran until roughly 3.077s. During that time msbuild was not running that much -- it was only using around 10% of 1 CPU. The most active process was MsMpEng, perhaps prompted by writes to the ETL file.

You might be able to reduce the volume of ETL and hence the likelihood of ETL file I/O by rerunning with fewer noisy apps open; looks like both chrome and devenv were waking up from time to time and adding events. Also maybe put your temp ETL into a directory that is excluded from the AV?

[AndyAyersMS]

The NI for Systems.Collections.dll was also loaded about this time; I can't tell if this was just going on independently or was triggered by jitting this method.

[davkean]

Thanks @AndyAyersMS, let me try and reduce the noise here. Is there a doc somewhere that tells me the best way to investigate if JIT is getting in our way to avoid bothering other devs unless needed? Basically, I'm looking certain at MSBuild runs, seeing that PerfView tells me that JIT is ~50% of CPU time and I want to basically translate that to actual impact on clock time it takes to run a build.

[karelz]

It should be the same as doing regular clock time analysis - you should not focus only on JIT as potential source of troubles - either it will pop or not.
PerfView has bunch of videos from Vance, incl. about clock-time perf analysis, but I bet you know about them already.

[davkean]

I watched Vance's videos a few months ago, but now I have a bunch more experience with PerfView they probably make a lot more sense. I'll go back and find that one.

[AndyAyersMS]

If you are seeing 50% exclusive time in clrjit.dll then yeah we should definitely investigate. If it is 50% inclusive then it may be the jit or it may be the way dependent assemblies and the classes they introduce are referenced.

[danmoseley]

@davkean did you figure out any more ?

[danmoseley]

@davkean ping on this one, should we leave it open?

[danmoseley]

No response on this one, I suggest we see whether it comes out of the next time we look at profiles.