MSBuild has non-trivial overhead due to JIT'ing

[davkean]

VisualStudio.15.IntPreview/15.3.0-pre.7.0+26730.0.d15rel

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

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)

In the above, the following binaries are JIT'd consuming 150ms of CPU time, is this expected?

Name	JitTimemsec	Num Methods	IL Size	Native Size
TOTAL	155.3	568	48,467	133,499
C:\Program Files (x86)\Microsoft Visual Studio\Preview\Enterprise\MSBuild\15.0\Bin\System.Collections.Immutable.dll	22.7	23	888	2,038
C:\Program Files (x86)\Microsoft Visual Studio\Preview\Enterprise\MSBuild\15.0\Bin\Microsoft.Build.dll	19.8	79	8,163	17,994
C:\Program Files (x86)\Microsoft Visual Studio\Preview\Enterprise\MSBuild\15.0\Bin\Microsoft.Build.Utilities.Core.dll	1.0	2	343	728
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.Framework.dll	0.5	5	169	335

[davkean]

When I tried to NGEN these binaries manually, it seems like they already had NGEN entries - are you passing MSBuild's config file to NGEN so that it generates images based on the binding policy?

[davkean]

Hmm, I tried manually passing a config or appbase to ngen and Immutable - it doesn't help, we still JIT it - perhaps it's just some of the generic methods that we can't produce native code up front for?

[davkean]

Use Advanced Group -> Jit Stats in PerfView to see what's being JIT'd.

[davkean]

I can see these NGEN images getting loaded:

But it appears that are exhibiting patterns that cause them to be JIT'd.

[davkean]

Note, I filed https://github.com/dotnet/corefx/issues/23125 against CoreFx for the Immutable JIT which mostly is 1 method.

[rainersigwald]

We ngen through the VSIX:

https://github.com/Microsoft/msbuild/blob/2d8a4341875e532bdf25a14f208f62a7bb547774/setup/files.swr#L25

RPS has caught performance regressions when we accidentally didn't in the past, as well as when our binding redirect mismatched with VS's. So the "they're NGENed but still getting JITted" theory rings true to me.

[benaadams]

when trying to run command in summary getting error

roslyn\src\Compilers\Core\CodeAnalysisTest\CodeAnalysisTest.csproj : 
 error MSB4057: The target "ReportAssetsLogMessages" does not exist in the project.

e.g.

C:\GitHub\roslyn\src\Compilers\Core\CodeAnalysisTest\CodeAnalysisTest.csproj : error MSB4057: The target "ReportAssetsLogMessages" does not exist in the project.

Project Evaluation Performance Summary:
     6005 ms  C:\GitHub\roslyn\src\Compilers\Core\CodeAnalysisTest\CodeAnalysisTest.csproj   1 calls

Project Performance Summary:
      378 ms  C:\GitHub\roslyn\src\Compilers\Core\CodeAnalysisTest\CodeAnalysisTest.csproj   1 calls
                378 ms  ReportAssetsLogMessages                    1 calls

Build FAILED.

C:\GitHub\roslyn\src\Compilers\Core\CodeAnalysisTest\CodeAnalysisTest.csproj : error MSB4057: The target "ReportAssetsLogMessages" does not exist in the project.
    0 Warning(s)
    1 Error(s)

Time Elapsed 00:00:08.60

[benaadams]

@davkean is there a roslyn branch that has ReportAssetsLogMessages? Can't find the jitted Immutable method

[davkean]

Need to be on 15.3 build.

[benaadams]

https://github.com/Microsoft/msbuild/tree/vs15.3 ?
Or https://github.com/dotnet/roslyn/tree/dev15.3.x ?

[davkean]

Ah, sorry - I thought we back ported this to 1.1, I'm guessing we didn't? If so, install the latest 2.0 CLI to get this target.

[benaadams]

Ah am running with CoreRun.exe as have to target standalone and its not producing an exe; will rummage. Know where to look now :)

[davkean]

It comes from http://github.com/dotnet/sdk.

[benaadams]

Ah, copied all the stuff from Microsoft Visual Studio\Preview\Enterprise\MSBuild (Sdk/Microsoft/15) to the MSBuild directory, mostly seems to work - now getting an issue reading registry for CodeAnalysis

C:\GitHub\msbuild\bin\Release-NetCore\AnyCPU\Windows_NT\Windows_NT_Deployment>.\CoreRun.exe MSBuild.dll  /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=C:\\GitHub\\roslyn\\;SolutionExt=.sln;BuildingInsideVisualStudio=true;DefineExplicitDefaults=true;Platform=AnyCPU;SolutionPath=C:\\GitHub\\roslyn\\Roslyn.sln;SolutionName=Roslyn;DevEnvDir=C:\Program Files (x86)\Microsoft Visual Studio\Preview\Enterprise\Common7\IDE;BuildingProject=false" C:\GitHub\roslyn\src\Compilers\Core\CodeAnalysisTest\CodeAnalysisTest.csproj
C:\GitHub\msbuild\bin\Release-NetCore\AnyCPU\Windows_NT\Windows_NT_Deployment\Microsoft\VisualStudio\v15.0\CodeAnalysis\

Microsoft.CodeAnalysis.targets(26,5): error MSB4184: The expression 
"Registry:HKEY_LOCAL_MACHINE\Software\Microsoft\VisualStudio\15.0\Setup\EDev@StanDir" 
cannot be evaluated.  [C:\GitHub\roslyn\src\Compilers\Core\CodeAnalysisTest\CodeAnalysisTest.csproj]

Project Evaluation Performance Summary:
        0 ms  C:\GitHub\roslyn\src\Compilers\Core\CodeAnalysisTest\CodeAnalysisTest.csproj   1 calls

Project Performance Summary:
      126 ms  C:\GitHub\roslyn\src\Compilers\Core\CodeAnalysisTest\CodeAnalysisTest.csproj   1 calls
                126 ms  ReportAssetsLogMessages                    1 calls

Build FAILED.

C:\GitHub\msbuild\bin\Release-NetCore\AnyCPU\Windows_NT\Windows_NT_Deployment\Microsoft\VisualStudio\v15.0\CodeAnalysis\Microsoft.CodeAnalysis.targets(26,5): 
error MSB4184: The expression "Registry:HKEY_LOCAL_MACHINE\Software\Microsoft\VisualStudio\15.0\Setup\EDev@StanDir" 
cannot be evaluated.  [C:\GitHub\roslyn\src\Compilers\Core\CodeAnalysisTest\CodeAnalysisTest.csproj]
    0 Warning(s)
    1 Error(s)

Time Elapsed 00:00:05.19

Can keep looking if you have any tips?