Loading NuGet/JSON.NET binaries adds ~130ms to a build

[davkean]

1. Enlist in Roslyn (assuming e:\Roslyn, otherwise change paths)
2. Restore.cmd

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\Core\CodeAnalysisTest\CodeAnalysisTest.csproj

Project Evaluation Performance Summary:
      149 ms  E:\roslyn\src\Compilers\Core\CodeAnalysisTest\CodeAnalysisTest.csproj   1 calls

Project Performance Summary:
      142 ms  E:\roslyn\src\Compilers\Core\CodeAnalysisTest\CodeAnalysisTest.csproj   1 calls
                142 ms  ReportAssetsLogMessages                    1 calls

Target Performance Summary:
      141 ms  ReportAssetsLogMessages                    1 calls

Task Performance Summary:
      134 ms  ReportAssetsLogMessages                    1 calls

Build succeeded.
    0 Warning(s)
    0 Error(s)

[davkean]

This target runs in design-time build, and we want the entire design-time build to be under 100 ms - for this project just this one target is 141 ms.

[davkean]

Excluding evaluation time, 50% of the time is just reading the file:

[davkean]

Of which, 9% over total build minus evaluation is just accessing this property:

[davkean]

Looks like we're spending 35% of CPU time just JITing:

Name	JitTimemsec	Num Methods	IL Size	Native Size
TOTAL	145.8	560	47,937	132,010
C:\Program Files (x86)\Microsoft Visual Studio\Preview\Enterprise\MSBuild\Sdks\Microsoft.NET.Sdk\tools\net46\Newtonsoft.Json.dll	28.5	115	13,705	28,194
C:\Program Files (x86)\Microsoft Visual Studio\Preview\Enterprise\MSBuild\Sdks\Microsoft.NET.Sdk\tools\net46\NuGet.ProjectModel.dll	24.4	89	7,291	16,727
C:\Program Files (x86)\Microsoft Visual Studio\Preview\Enterprise\MSBuild\15.0\Bin\Microsoft.Build.dll	23.1	90	8,749	19,600
C:\Program Files (x86)\Microsoft Visual Studio\Preview\Enterprise\MSBuild\15.0\Bin\System.Collections.Immutable.dll	22.7	28	1,177	2,474
C:\Program Files (x86)\Microsoft Visual Studio\Preview\Enterprise\MSBuild\Sdks\Microsoft.NET.Sdk\tools\net46\NuGet.Frameworks.dll	19.3	105	15,081	35,996
C:\WINDOWS\Microsoft.Net\assembly\GAC_32\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll	7.6	43	4,165	8,009
C:\WINDOWS\Microsoft.Net\assembly\GAC_MSIL\System.Core\v4.0_4.0.0.0__b77a5c561934e089\System.Core.dll	6.0	16	993	3,543
C:\WINDOWS\Microsoft.Net\assembly\GAC_MSIL\System\v4.0_4.0.0.0__b77a5c561934e089\System.dll	3.5	12	246	5,518
C:\Program Files (x86)\Microsoft Visual Studio\Preview\Enterprise\MSBuild\Sdks\Microsoft.NET.Sdk\tools\net46\Microsoft.NET.Build.Tasks.dll	2.7	11	383	888
C:\Program Files (x86)\Microsoft Visual Studio\Preview\Enterprise\MSBuild\Sdks\Microsoft.NET.Sdk\tools\net46\NuGet.Versioning.dll	2.4	19	1,835	3,937
C:\Program Files (x86)\Microsoft Visual Studio\Preview\Enterprise\MSBuild\Sdks\Microsoft.NET.Sdk\tools\net46\NuGet.LibraryModel.dll	2.3	32	1,933	4,001
C:\Program Files (x86)\Microsoft Visual Studio\Preview\Enterprise\MSBuild\Sdks\Microsoft.NET.Sdk\tools\net46\NuGet.Packaging.dll	1.4	12	496	1,349
C:\Program Files (x86)\Microsoft Visual Studio\Preview\Enterprise\MSBuild\15.0\bin\MSBuild.exe	0.8	1	67	153
C:\Program Files (x86)\Microsoft Visual Studio\Preview\Enterprise\MSBuild\15.0\Bin\Microsoft.Build.Utilities.Core.dll	0.6	2	343	728
C:\Program Files (x86)\Microsoft Visual Studio\Preview\Enterprise\MSBuild\15.0\Bin\Microsoft.Build.Framework.dll	0.4	5	169	335
C:\Program Files (x86)\Microsoft Visual Studio\Preview\Enterprise\MSBuild\Sdks\Microsoft.NET.Sdk\tools\net46\NuGet.Common.dll	0.1	4	161	342
C:\Program Files (x86)\Microsoft Visual Studio\Preview\Enterprise\MSBuild\Sdks\Microsoft.NET.Sdk\tools\net46\NuGet.Packaging.Core.dll	0.0	3	93	216

[davkean]

All this just to read a text file and convert it to XML.

[davkean]

Okay, from what I can figure out - there's ~130 ms of just "overhead", loading binaries, JIT'ing, running initialization as soon as we go to read the lock file. The overhead of actually reading the lock file is much less, but still high in some cases ~40 ms (src\Test\DeployCoreClrTestRuntime\DeployCoreClrTestRuntime.csproj for example).

We should figure out how we stop paying for that overhead on every build, node reuse will help - but we really need to consider if we want to pay for this 130 ms on first launch.

I'm going to leave this bug as the overhead and file a separate bug for the parsing itself.

[davkean]

All these binaries (excluding MSBuild ones which I'm tracking via: dotnet/msbuild#2419) are loading via LoadForm - so even if NGEN or even if they are already NGEN'd we're not going to pick up the images.

[davkean]

Here's another trace from running a normal design-time build, I've crossed out the ones that are owned by MSBuild:

Name	JitTimemsec	Num Methods	IL Size	Native Size
TOTAL	196.7	787	58,266	184,373
TOTAL (Minus MSBuild binaries)	120.6
C:\Program Files\dotnet\sdk\2.0.0-preview2-006497\Sdks\Microsoft.NET.Sdk\tools\net46\Newtonsoft.Json.dll	35.2	119	14,229	29,176
C:\Program Files\dotnet\sdk\2.0.0-preview2-006497\Sdks\Microsoft.NET.Sdk\tools\net46\NuGet.ProjectModel.dll	31.3	97	7,650	17,655
C:\Program Files (x86)\Microsoft Visual Studio\Preview\Enterprise\MSBuild\15.0\Bin\Microsoft.Build.dll	30.1	108	8,825	20,905
C:\Program Files\dotnet\sdk\2.0.0-preview2-006497\Sdks\Microsoft.NET.Sdk\tools\net46\NuGet.Frameworks.dll	22.7	116	15,945	37,653
C:\Program Files\dotnet\sdk\2.0.0-preview2-006497\Sdks\Microsoft.NET.Sdk\tools\net46\Microsoft.NET.Build.Tasks.dll	17.7	129	7,043	14,981
C:\WINDOWS\Microsoft.Net\assembly\GAC_MSIL\System\v4.0_4.0.0.0__b77a5c561934e089\System.dll	17.4	15	246	30,881
C:\WINDOWS\Microsoft.Net\assembly\GAC_MSIL\System.Core\v4.0_4.0.0.0__b77a5c561934e089\System.Core.dll	10.4	26	1,919	5,090
C:\WINDOWS\Microsoft.Net\assembly\GAC_32\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll	7.8	47	3,760	6,739
C:\Program Files (x86)\Microsoft Visual Studio\Preview\Enterprise\MSBuild\15.0\Bin\System.Collections.Immutable.dll	6.1	24	667	1,705
C:\Program Files\dotnet\sdk\2.0.0-preview2-006497\Sdks\Microsoft.NET.Sdk\tools\net46\NuGet.Versioning.dll	4.8	33	2,783	5,695
C:\Program Files (x86)\Microsoft Visual Studio\Preview\Enterprise\MSBuild\15.0\bin\SdkResolvers\Microsoft.DotNet.MSBuildSdkResolver\Microsoft.DotNet.MSBuildSdkResolver.dll	4.2	24	1,539	3,769
C:\Program Files\dotnet\sdk\2.0.0-preview2-006497\Sdks\Microsoft.NET.Sdk\tools\net46\NuGet.LibraryModel.dll	2.4	28	1,796	3,636
C:\Program Files\dotnet\sdk\2.0.0-preview2-006497\Sdks\Microsoft.NET.Sdk\tools\net46\NuGet.Packaging.dll	2.0	17	733	2,269
C:\Program Files (x86)\Microsoft Visual Studio\Preview\Enterprise\MSBuild\15.0\Bin\Microsoft.Build.Framework.dll	1.7	17	591	1,213
C:\Program Files\dotnet\sdk\2.0.0-preview2-006497\Sdks\Microsoft.NET.Sdk\tools\net46\NuGet.Common.dll	0.9	13	580	1,158
C:\Program Files (x86)\Microsoft Visual Studio\Preview\Enterprise\MSBuild\15.0\bin\MSBuild.exe	0.7	1	67	153
C:\Program Files (x86)\Microsoft Visual Studio\Preview\Enterprise\MSBuild\15.0\Bin\Microsoft.Build.Utilities.Core.dll	0.6	2	343	728
C:\Program Files (x86)\Microsoft Visual Studio\Preview\Enterprise\MSBuild\15.0\Bin\Microsoft.Build.Tasks.Core.dll	0.4	2	180	394
C:\Program Files\dotnet\sdk\2.0.0-preview2-006497\Sdks\Microsoft.NET.Sdk\tools\net46\NuGet.Configuration.dll	0.2	2	134	239
C:\Program Files\dotnet\sdk\2.0.0-preview2-006497\Sdks\Microsoft.NET.Sdk\tools\net46\NuGet.Packaging.Core.dll	0.1	4	164	334