Adding .NET Standard/.NET Framework facades assemblies is consuming 11% of build time #442

davkean · 2017-08-15T05:58:56Z

Investigating a customer's solution which is experiencing performance issues due to slow design-time builds even with <DefaultCompileItems>false</DefaultCompileItems> set, 4% of a design-time build is just finding the .NET Standard refs:

standard/netstandard/pkg/targets/NETStandard.Library.targets

Lines 7 to 16 in bbbfd46

    
           <Reference Condition="'$(_NetStandardLibraryRefPath)' != ''" Include="$(_NetStandardLibraryRefPath)*.dll"> 
        
             <!-- Private = false to make these reference only --> 
        
             <Private>false</Private> 
        
             <!-- hide these from Assemblies view in Solution Explorer, they will be shown under packages --> 
        
             <Visible>false</Visible> 
        
             <Facade Condition="'%(FileName)' != 'netstandard'">true</Facade> 
        
             <NuGetPackageId>NETStandard.Library</NuGetPackageId> 
        
             <NuGetPackageVersion>$(NETStandardLibraryPackageVersion)</NuGetPackageVersion> 
        
           </Reference> 
        
           <ReferenceCopyLocalPaths Condition="'$(_NetStandardLibraryLibPath)' != ''" Include="$(_NetStandardLibraryLibPath)*.dll">

This is on my SSD, on a slow disk like the customer was running this probably takes even longer.

When I remove these includes, I go from:

to:

To avoid paying for this lookup over and over again when these are a fixed set of files, can we please auto-generate this?

The text was updated successfully, but these errors were encountered:

davkean · 2017-08-15T06:01:58Z

Make note that we're paying for these lookups not only when this a .NET Standard project is built, but also everytime the project is evaluated - which occurs when another project references this project and calls into it to call GetTargetPath, so if you have lots of these projects, similar to the customer, this adds up very quickly.

davkean · 2017-08-16T00:24:55Z

Note, while in the trace I'm looking at consumes 4% of the CPU - the overhead is much more than that.

Remove these includes makes the design-time build 20% faster, a standard alone project targeting .NET Standard 2.0 went from 0.42 secs -> 0.34 secs.

ericstj · 2017-08-31T16:24:13Z

Interesting, I wonder why this wasn't an issue for PCL / desktop facades. Is it because of the metadata and condition? Or perhaps because those happen in a target?

@davkean in your measurements did you replace these with static items, or did you remove entirely. I can imagine that removing entirely will greatly improve things since you take away all the references.

One thing we could do is make this only use netstandard.dll by default and only bring in facades if something references System.Runtime.

davkean · 2017-09-01T01:00:22Z

ImplicitlyExpandDesignTimeFacades is a issue, it's the 5th slowest target in a design time build.

This particular case is worse because it happens in an evaluation, which means a project pays this evaluation twice for each reference (once in ResolveProjectRefererences and once in GetProjectReferenceTargetFrameworkProperties) and once for itself. We also block the UI thread on an evaluation in some cases - so this can slow down other parts of VS.

davkean · 2017-09-01T02:37:44Z

We're also talking about a huge increase in assemblies, according to @terrajobst:

4.6.1
53 (built-in facades) + 114 (.NET Standard 2.0 facades) = 166 facades

4.7.1
104 (built-in facades)

ericstj · 2017-09-07T22:34:54Z

4.6.1 and 4.7.1 are the same, we don't feed duplicates through.

We can remove the wildcard, but will that move the needle? Do we also need to move things into a target? Will that be enough?

The reason I raise these questions is because the analysis removed the assemblies completely which isn't a valid scenario.

If you can share your method for measuring we can do some of this ourselves.

ericstj · 2017-09-08T15:39:42Z

So I took a guess at a method to examine evaluation cost.

I created an empty target in a project that had no dependencies. I then build just that target, then measure the performance of the command. This should mean that the majority of time is spent doing evaluation + some constant cost. We can eliminate constant cost with a control.

I then created three cases:

The current wild-card based solution.
A static list (where I'm careful to never used any file-based metadata).
Remove the references completely.

The last is the control. That should help us measure constant cost without adding any of these references.

I'll run an experiment and share the results.

ericstj · 2017-09-08T20:12:35Z

Here's my measurements; 500 samples each, millisecond duration to run msbuild /t:NoopTarget.

Measure	Control	Wildcard	Static list
Median	248.8213	255.3852	255.223
Mean	251.6705	259.0837	261.5093
STDDEV	20.64927	24.8463	29.03676

I'm not seeing the difference reported in this issue.

Here's the potential fix, but we need to be able to reproduce the performance issue in order to confirm this fixes it. ericstj@1a06278

davkean · 2017-09-13T03:03:32Z

Daniel wrote an evaluation profiler so I can see the real cost here - I'm seeing that this costs between 8 - 10 ms per evaluation (the 4th highest expression)

Given a project that has 12 .NET Framework project references, and consumes 1 .NET Standard library, that cost would be approximately:

2 evaluations x 12 references x 10 ms == 240 ms (note we're double-evaluating references right now)
1 evaluation x 1 project x 10 ms == 10ms

Total: 250ms.

Still playing around with the profiler - but will point to a bug that calls out all costs when I'm finished.

Update: That seems to fit with your "control".

I would rather we push this out of evaluation and into a target. I don't know where we landed with the dependency node - so that will be need to be factored in.

davkean · 2017-09-13T05:22:25Z

I've now got the evaluation profiler working in a state that let's me capture numbers across an entire solution. Here's the cost of these expressions if we were to do a solution-wide design-time build of the private customer solution that I've been testing with here: dotnet/project-system#2789.

This is the top 6 expressions:

File	Line Number	Element	Expression	Inclusive (ms)	Exclusive (ms)
NETStandard.Library.NETFramework.targets	3	_NETStandardLibraryNETFrameworkReference	`<_NETStandardLibraryNETFrameworkReference Include="$(MSBuildThisFileDirectory)\ref\*.dll" Exclude="@(_NETStandardLibraryNETFrameworkReference->'$(MSBuildThisFileDirectory)\ref\%(FileName).dll'" />`	580.7	580.8
NETStandard.Library.NETFramework.targets	6	_NETStandardLibraryNETFrameworkLib	`<_NETStandardLibraryNETFrameworkLib Include="$(MSBuildThisFileDirectory)\lib\*.dll" Exclude="@(_NETStandardLibraryNETFrameworkLib->'$(MSBuildThisFileDirectory)\ref\%(FileName).dll'" />`	516.5	516.5
NETStandard.Library.targets	7	Reference	<Reference Condition="'$(_NetStandardLibraryRefPath)' != ''" Include="$(_NetStandardLibraryRefPath)*.dll" ><!-- Private = false to make these reference only --><Private>false</Private><!-- hide these from Assemblies view in Solution Explorer, they will be shown under packages --><Visible>false</Visible><Facade Condition="'%(FileName)' != 'netstandard'">true</Facade><NuGetPackageId>NETStandard.Library</NuGetPackageId><NuGetPackageVersion>$(NETStandardLibraryPackageVersion)</NuGetPackageVersion></Reference>	298.3	262.6
Microsoft.Managed.DesignTime.targets	46	ManagedXamlResourcesDirectory	`<ManagedXamlResourcesDirectory Condition="!Exists('$(ManagedXamlResourcesDirectory)')" >$(MSBuildThisFileDirectory)$(LangName.Split('-')[0])</ManagedXamlResourcesDirectory>`	116.4	113.8
Microsoft.Common.CurrentVersion.targets	92	TargetPlatformSdkPath	`<TargetPlatformSdkPath Condition="'$(TargetPlatformSdkPath)' == ''" >$([Microsoft.Build.Utilities.ToolLocationHelper]::GetPlatformSDKLocation($(TargetPlatformIdentifier), $(TargetPlatformVersion)))</TargetPlatformSdkPath>`	53.7	52.8
Microsoft.Common.CurrentVersion.targets	83	FrameworkPathOverride	`<FrameworkPathOverride Condition="'$(FrameworkPathOverride)' == ''" >$([Microsoft.Build.Utilities.ToolLocationHelper]::GetPathToStandardLibraries($(TargetFrameworkIdentifier), $(TargetFrameworkVersion), $(TargetFrameworkProfile), $(PlatformTarget), $(TargetFrameworkRootPath)))</FrameworkPathOverride>`	52.5	51.8

The costs look cheaper than what I've called out above, but still high - note the other two items from .NETStandard.Library.NETFramework.targets that are also showing up.

ericstj · 2017-09-13T17:34:13Z

If you'd like to try the proposed solution you can use NETStandard.Library.2.1.0-preview1-25708-0 from https://www.myget.org/F/ericstj-issue-repros/api/v3/index.json. If you'd like to minimize the change, you can just grab the targets out of there and overwrite the ones in your NS.L package.

For .NETStandard.Library.NETFramework.targets it'll get slightly better with dotnet/sdk#1582. We can additionally use the list technique there if we find that it helps.

edit: Here's a commit that uses the list technique in the SDK: ericstj/sdk@fa705a3

davkean · 2017-09-14T06:03:54Z

Here's an update with the final numbers and a breakdown of the passes:

Total build time: 13140 ms
Total evaluation time: 6060 ms

Pass	File	Line Number	Expression	Inc (ms)	Inc (%)	Exc (ms)	Exc (%)	Call Count	This repro?
Total Evaluation				6060	100%	52	1%
Properties (Pass 1)				3343	55%	8	0%
ItemDefinitionGroup (Pass 2)				14	0%	2	0%
Items (Pass 3)				477	8%	19	0%
Lazy Items (Pass 3.1)				1795	30%	156	3%
UsingTasks (Pass 4)				64	1%	64	1%
Targets (Pass 5)				314	5%	177	3%
Lazy Items (Pass 3.1)	NETStandard.Library.NETFramework.targets	3	`<_NETStandardLibraryNETFrameworkReference Include="$(MSBuildThisFileDirectory)\ref\*.dll" Exclude="@...`	587	10%	587	10%	126	<---- This repo
Lazy Items (Pass 3.1)	NETStandard.Library.NETFramework.targets	6	`<_NETStandardLibraryNETFrameworkLib Include="$(MSBuildThisFileDirectory)\lib\*.dll" Exclude="@(_NETS...`	527	9%	527	9%	126	<---- This repo
Lazy Items (Pass 3.1)	NETStandard.Library.targets	7	`<Reference Condition="'$(_NetStandardLibraryRefPath)' != ''" Include="$(_NetStandardLibraryRefPath)*...`	322	5%	284	5%	43	<---- This repo
Properties (Pass 1)	Microsoft.Common.CurrentVersion.targets	114	`<Import Project="$(CommonTargetsPath)" />`	2105	35%	145	2%	223
Properties (Pass 1)	Microsoft.Managed.DesignTime.targets	46	`<ManagedXamlResourcesDirectory Condition="!Exists('$(ManagedXamlResourcesDirectory)')" >$(MSBuildThi...`	108	2%	106	2%	223
Properties (Pass 1)	Microsoft.CSharp.CurrentVersion.targets	27	`<Import Project="$(MSBuildUserExtensionsPath)\$(MSBuildToolsVersion)\Microsoft.CSharp.targets\Import...`	177	3%	56	1%	223
Properties (Pass 1)	Microsoft.Common.CurrentVersion.targets	92	`<TargetPlatformSdkPath Condition="'$(TargetPlatformSdkPath)' == ''" >$([Microsoft.Build.Utilities.To...`	57	1%	56	1%	223
Properties (Pass 1)	Microsoft.Common.props	77	`<Import Project="$(MSBuildUserExtensionsPath)\$(MSBuildToolsVersion)\Imports\Microsoft.Common.props\...`	100	2%	55	1%	223
Properties (Pass 1)	Microsoft.Common.CurrentVersion.targets	83	`<FrameworkPathOverride Condition="'$(FrameworkPathOverride)' == ''" >$([Microsoft.Build.Utilities.To...`	50	1%	49	1%	223
Properties (Pass 1)	Microsoft.Common.CurrentVersion.targets	5821	`<Import Project="$(MSBuildExtensionsPath)\$(MSBuildToolsVersion)\Microsoft.Common.targets\ImportAfte...`	624	10%	48	1%	223
Lazy Items (Pass 3.1)	Microsoft.Common.CurrentVersion.targets	369	`<_DebugSymbolsOutputPath Include="@(_DebugSymbolsIntermediatePath->'$(OutDir)%(Filename)%(Extensi...`	43	1%	43	1%	223
Properties (Pass 1)	Microsoft.NET.Build.Extensions.targets	18	`<_TargetFrameworkVersionWithoutV Condition="$(TargetFrameworkVersion.StartsWith('v'))" >$(TargetFram...`	45	1%	42	1%	223
Properties (Pass 1)	Microsoft.Common.props	78	`<Import Project="$(MSBuildExtensionsPath)\$(MSBuildToolsVersion)\Imports\Microsoft.Common.props\Impo...`	79	1%	41	1%	223
Lazy Items (Pass 3.1)	NETStandard.Library.targets	12	`Condition="'%(FileName)' != 'netstandard'")`	39	1%	39	1%	43	<---- This repo

In summary, for this mixed solution, all .NETStandard.Library.* accounts for 25% of all evaluation time, or 11% of total build time.

Would you like individual bugs for this or do you want to track it with this?

davkean · 2017-09-14T07:59:11Z

Note, I filed #494 to track the last one.

davkean · 2017-09-14T09:19:05Z

Here's another view by inclusive time: https://gist.github.com/davkean/ca084b63636e5eac0544088f2ceb8ad2.

ericstj · 2017-09-14T15:58:18Z

@davkean you need to either provide this tool or test the proposed fix to tell us if it resolves the issue. Note that the fix I've provided also addresses the last item.

davkean · 2017-09-14T19:56:44Z

I'm not ignoring the questions, I was still focusing on data gathering mode. Code isn't quite ready to be consumed. I can try your changes today.

davkean · 2017-09-19T04:05:55Z

Sorry for the late reply I was OOF yesterday.

I ran the numbers, here's what I got:

Before

Pass	File	Line #	Expression	Inc (ms)	Inc (%)	Exc (ms)	Exc (%)	#
Total Evaluation				3864	100%	16	0.4%
Initial Properties (Pass 0)				19	0.5%	19	0.5%
Properties (Pass 1)				2501	64.7%	4	0.1%
ItemDefinitionGroup (Pass 2)				11	0.3%	1	0%
Items (Pass 3)				407	10.5%	12	0.3%
Lazy Items (Pass 3.1)				607	15.7%	108	2.8%
UsingTasks (Pass 4)				49	1.3%	49	1.3%
Targets (Pass 5)				252	6.5%	142	3.7%
Lazy Items (Pass 3.1)	NETStandard.Library.targets	7	`<Reference Condition="'$(_NetStandardLibraryRefPath)' != ''" Include="$(_NetStandardLibraryRefPath)*...`	297	7.7%	265	6.8%	43
Properties (Pass 1)	Microsoft.Managed.DesignTime.targets	46	`<ManagedXamlResourcesDirectory Condition="!Exists('$(ManagedXamlResourcesDirectory)')" >$(MSBuildThi...`	108	2.8%	106	2.7%	223
Properties (Pass 1)	Microsoft.Common.props	63	`<Import Project="$(MSBuildProjectExtensionsPath)$(MSBuildProjectFile).*.props" Condition="'$(ImportP...`	84	2.2%	65	1.7%	223
Properties (Pass 1)	Microsoft.Common.CurrentVersion.targets	5821	`<Import Project="$(MSBuildExtensionsPath)\$(MSBuildToolsVersion)\Microsoft.Common.targets\ImportAfte...`	278	7.2%	55	1.4%	223
Properties (Pass 1)	Microsoft.Common.CurrentVersion.targets			1549	40.1%	53	1.4%	223
Properties (Pass 1)	Microsoft.Common.targets	127	`<Import Project="$(MSBuildProjectExtensionsPath)$(MSBuildProjectFile).*.targets" Condition="'$(Impor...`	104	2.7%	52	1.4%	223
Properties (Pass 1)	Microsoft.Common.CurrentVersion.targets	92	`<TargetPlatformSdkPath Condition="'$(TargetPlatformSdkPath)' == ''" >$([Microsoft.Build.Utilities.To...`	48	1.2%	47	1.2%	223
Properties (Pass 1)	Microsoft.Common.CurrentVersion.targets	83	`<FrameworkPathOverride Condition="'$(FrameworkPathOverride)' == ''" >$([Microsoft.Build.Utilities.To...`	40	1%	40	1%	223
Properties (Pass 1)	Microsoft.NET.Build.Extensions.targets	18	`<_TargetFrameworkVersionWithoutV Condition="$(TargetFrameworkVersion.StartsWith('v'))" >$(TargetFram...`	42	1.1%	40	1%	223
Properties (Pass 1)	Microsoft.Common.props	78	`<Import Project="$(MSBuildExtensionsPath)\$(MSBuildToolsVersion)\Imports\Microsoft.Common.props\Impo...`	68	1.8%	40	1%	223
Properties (Pass 1)	Microsoft.Common.props	77	`<Import Project="$(MSBuildUserExtensionsPath)\$(MSBuildToolsVersion)\Imports\Microsoft.Common.props\...`	47	1.2%	39	1%	223
Properties (Pass 1)	Microsoft.CSharp.CurrentVersion.targets	27	`<Import Project="$(MSBuildUserExtensionsPath)\$(MSBuildToolsVersion)\Microsoft.CSharp.targets\Import...`	47	1.2%	38	1%	223
Lazy Items (Pass 3.1)	NETStandard.Library.targets	12	`Condition="'%(FileName)' != 'netstandard'")`	33	0.8%	33	0.8%	43

After

Pass	File	Line #	Expression	Inc (ms)	Inc (%)	Exc (ms)	Exc (%)	#
Total Evaluation				3469	100%	16	0.5%
Initial Properties (Pass 0)				19	0.6%	19	0.6%
Properties (Pass 1)				2451	70.7%	5	0.1%
ItemDefinitionGroup (Pass 2)				11	0.3%	1	0%
Items (Pass 3)				375	10.8%	20	0.6%
Lazy Items (Pass 3.1)				325	9.4%	95	2.7%
UsingTasks (Pass 4)				54	1.6%	54	1.6%
Targets (Pass 5)				217	6.3%	122	3.5%
Properties (Pass 1)	Microsoft.Managed.DesignTime.targets	46	`<ManagedXamlResourcesDirectory Condition="!Exists('$(ManagedXamlResourcesDirectory)')" >$(MSBuildThi...`	103	3%	101	2.9%	223
Properties (Pass 1)	Microsoft.Common.CurrentVersion.targets			1541	44.4%	56	1.6%	223
Properties (Pass 1)	Microsoft.Common.CurrentVersion.targets	5821	`<Import Project="$(MSBuildExtensionsPath)\$(MSBuildToolsVersion)\Microsoft.Common.targets\ImportAfte...`	250	7.2%	53	1.5%	223
Properties (Pass 1)	Microsoft.Common.props	63	`<Import Project="$(MSBuildProjectExtensionsPath)$(MSBuildProjectFile).*.props" Condition="'$(ImportP...`	68	2%	50	1.4%	223
Properties (Pass 1)	Microsoft.Common.targets	127	`<Import Project="$(MSBuildProjectExtensionsPath)$(MSBuildProjectFile).*.targets" Condition="'$(Impor...`	93	2.7%	50	1.4%	223
Properties (Pass 1)	Microsoft.CSharp.CurrentVersion.targets	27	`<Import Project="$(MSBuildUserExtensionsPath)\$(MSBuildToolsVersion)\Microsoft.CSharp.targets\Import...`	55	1.6%	46	1.3%	223
Properties (Pass 1)	Microsoft.Common.props	78	`<Import Project="$(MSBuildExtensionsPath)\$(MSBuildToolsVersion)\Imports\Microsoft.Common.props\Impo...`	71	2%	44	1.3%	223
Properties (Pass 1)	Microsoft.Common.CurrentVersion.targets	92	`<TargetPlatformSdkPath Condition="'$(TargetPlatformSdkPath)' == ''" >$([Microsoft.Build.Utilities.To...`	44	1.3%	43	1.2%	223
Properties (Pass 1)	Microsoft.Common.CurrentVersion.targets	83	`<FrameworkPathOverride Condition="'$(FrameworkPathOverride)' == ''" >$([Microsoft.Build.Utilities.To...`	44	1.3%	43	1.2%	223
Properties (Pass 1)	Microsoft.NET.Build.Extensions.targets	18	`<_TargetFrameworkVersionWithoutV Condition="$(TargetFrameworkVersion.StartsWith('v'))" >$(TargetFram...`	41	1.2%	38	1.1%	223
Properties (Pass 1)	Microsoft.Common.props	77	`<Import Project="$(MSBuildUserExtensionsPath)\$(MSBuildToolsVersion)\Imports\Microsoft.Common.props\...`	46	1.3%	38	1.1%	223

All I did was replace the targets, but if I look at the targets themselves, I don't understand the change:

 <ItemGroup Condition="'@(_NetStandardLibraryRef)' != ''">
    <Reference Include="@(_NetStandardLibraryRef)">
      <!-- Private = false to make these reference only -->
      <Private>false</Private>
      <!-- hide these from Assemblies view in Solution Explorer, they will be shown under packages -->
      <Visible>false</Visible>
      <NuGetPackageId>NETStandard.Library</NuGetPackageId>
      <NuGetPackageVersion>$(NETStandardLibraryPackageVersion)</NuGetPackageVersion>
    </Reference>
  </ItemGroup>

Where does this _NetStandardLibraryRef item come from?

ericstj · 2017-09-19T15:21:52Z

_NetStandardLibraryRef comes from the netstandard2.0-specific targets file (build\netstandard2.0\NETStandard.Library.targets). Here's what it looks like in the sample package I shared:

<Project xmlns="http://schemas.microsoft.com/developer/msbuild/2003">
  <!-- Only add references if we're actually targeting .NETStandard.
       If the project is targeting some other TFM that is compatible with NETStandard we expect
       that framework to provide all references for NETStandard, mscorlib, System.* in their own
       targeting pack / SDK. -->
  <ItemGroup Condition="'$(TargetFrameworkIdentifier)' == '.NETStandard'">
    <_NetStandardLibraryRefFile Include="netstandard" />
    <_NetStandardLibraryRefFile Include="Microsoft.Win32.Primitives;Microsoft.Win32.Primitives;System.AppContext;System.AppContext;System.Collections.Concurrent;System.Collections.Concurrent;System.Collections;System.Collections;System.Collections.NonGeneric;System.Collections.NonGeneric;System.Collections.Specialized;System.Collections.Specialized;System.ComponentModel;System.ComponentModel;System.ComponentModel.EventBasedAsync;System.ComponentModel.EventBasedAsync;System.ComponentModel.Primitives;System.ComponentModel.Primitives;System.ComponentModel.TypeConverter;System.ComponentModel.TypeConverter;System.Console;System.Console;System.Data.Common;System.Data.Common;System.Diagnostics.Contracts;System.Diagnostics.Contracts;System.Diagnostics.Debug;System.Diagnostics.Debug;System.Diagnostics.FileVersionInfo;System.Diagnostics.FileVersionInfo;System.Diagnostics.Process;System.Diagnostics.Process;System.Diagnostics.StackTrace;System.Diagnostics.StackTrace;System.Diagnostics.TextWriterTraceListener;System.Diagnostics.TextWriterTraceListener;System.Diagnostics.Tools;System.Diagnostics.Tools;System.Diagnostics.TraceSource;System.Diagnostics.TraceSource;System.Diagnostics.Tracing;System.Diagnostics.Tracing;System.Drawing.Primitives;System.Drawing.Primitives;System.Dynamic.Runtime;System.Dynamic.Runtime;System.Globalization.Calendars;System.Globalization.Calendars;System.Globalization;System.Globalization;System.Globalization.Extensions;System.Globalization.Extensions;System.IO.Compression;System.IO.Compression;System.IO.Compression.ZipFile;System.IO.Compression.ZipFile;System.IO;System.IO;System.IO.FileSystem;System.IO.FileSystem;System.IO.FileSystem.DriveInfo;System.IO.FileSystem.DriveInfo;System.IO.FileSystem.Primitives;System.IO.FileSystem.Primitives;System.IO.FileSystem.Watcher;System.IO.FileSystem.Watcher;System.IO.IsolatedStorage;System.IO.IsolatedStorage;System.IO.MemoryMappedFiles;System.IO.MemoryMappedFiles;System.IO.Pipes;System.IO.Pipes;System.IO.UnmanagedMemoryStream;System.IO.UnmanagedMemoryStream;System.Linq;System.Linq;System.Linq.Expressions;System.Linq.Expressions;System.Linq.Parallel;System.Linq.Parallel;System.Linq.Queryable;System.Linq.Queryable;System.Net.Http;System.Net.Http;System.Net.NameResolution;System.Net.NameResolution;System.Net.NetworkInformation;System.Net.NetworkInformation;System.Net.Ping;System.Net.Ping;System.Net.Primitives;System.Net.Primitives;System.Net.Requests;System.Net.Requests;System.Net.Security;System.Net.Security;System.Net.Sockets;System.Net.Sockets;System.Net.WebHeaderCollection;System.Net.WebHeaderCollection;System.Net.WebSockets.Client;System.Net.WebSockets.Client;System.Net.WebSockets;System.Net.WebSockets;System.ObjectModel;System.ObjectModel;System.Reflection;System.Reflection;System.Reflection.Extensions;System.Reflection.Extensions;System.Reflection.Primitives;System.Reflection.Primitives;System.Resources.Reader;System.Resources.Reader;System.Resources.ResourceManager;System.Resources.ResourceManager;System.Resources.Writer;System.Resources.Writer;System.Runtime.CompilerServices.VisualC;System.Runtime.CompilerServices.VisualC;System.Runtime;System.Runtime;System.Runtime.Extensions;System.Runtime.Extensions;System.Runtime.Handles;System.Runtime.Handles;System.Runtime.InteropServices;System.Runtime.InteropServices;System.Runtime.InteropServices.RuntimeInformation;System.Runtime.InteropServices.RuntimeInformation;System.Runtime.Numerics;System.Runtime.Numerics;System.Runtime.Serialization.Formatters;System.Runtime.Serialization.Formatters;System.Runtime.Serialization.Json;System.Runtime.Serialization.Json;System.Runtime.Serialization.Primitives;System.Runtime.Serialization.Primitives;System.Runtime.Serialization.Xml;System.Runtime.Serialization.Xml;System.Security.Claims;System.Security.Claims;System.Security.Cryptography.Algorithms;System.Security.Cryptography.Algorithms;System.Security.Cryptography.Csp;System.Security.Cryptography.Csp;System.Security.Cryptography.Encoding;System.Security.Cryptography.Encoding;System.Security.Cryptography.Primitives;System.Security.Cryptography.Primitives;System.Security.Cryptography.X509Certificates;System.Security.Cryptography.X509Certificates;System.Security.Principal;System.Security.Principal;System.Security.SecureString;System.Security.SecureString;System.Text.Encoding;System.Text.Encoding;System.Text.Encoding.Extensions;System.Text.Encoding.Extensions;System.Text.RegularExpressions;System.Text.RegularExpressions;System.Threading;System.Threading;System.Threading.Overlapped;System.Threading.Overlapped;System.Threading.Tasks;System.Threading.Tasks;System.Threading.Tasks.Parallel;System.Threading.Tasks.Parallel;System.Threading.Thread;System.Threading.Thread;System.Threading.ThreadPool;System.Threading.ThreadPool;System.Threading.Timer;System.Threading.Timer;System.ValueTuple;System.ValueTuple;System.Xml.ReaderWriter;System.Xml.ReaderWriter;System.Xml.XDocument;System.Xml.XDocument;System.Xml.XmlDocument;System.Xml.XmlDocument;System.Xml.XmlSerializer;System.Xml.XmlSerializer;System.Xml.XPath;System.Xml.XPath;System.Xml.XPath.XDocument;System.Xml.XPath.XDocument;mscorlib;mscorlib;System.ComponentModel.Composition;System.ComponentModel.Composition;System.Core;System.Core;System;System;System.Data;System.Data;System.Drawing;System.Drawing;System.IO.Compression.FileSystem;System.IO.Compression.FileSystem;System.Net;System.Net;System.Numerics;System.Numerics;System.Runtime.Serialization;System.Runtime.Serialization;System.ServiceModel.Web;System.ServiceModel.Web;System.Transactions;System.Transactions;System.Web;System.Web;System.Windows;System.Windows;System.Xml;System.Xml;System.Xml.Linq;System.Xml.Linq;System.Xml.Serialization;System.Xml.Serialization;Microsoft.Win32.Primitives.Forwards;_AssemblyInfo;System.AppContext.Forwards;_AssemblyInfo;System.Collections.Concurrent.Forwards;_AssemblyInfo;System.Collections.Forwards;_AssemblyInfo;System.Collections.NonGeneric.Forwards;_AssemblyInfo;System.Collections.Specialized.Forwards;_AssemblyInfo;System.ComponentModel.Forwards;_AssemblyInfo;System.ComponentModel.EventBasedAsync.Forwards;_AssemblyInfo;System.ComponentModel.Primitives.Forwards;_AssemblyInfo;System.ComponentModel.TypeConverter.Forwards;_AssemblyInfo;System.Console.Forwards;_AssemblyInfo;System.Data.Common.Forwards;_AssemblyInfo;System.Diagnostics.Contracts.Forwards;_AssemblyInfo;System.Diagnostics.Debug.Forwards;_AssemblyInfo;System.Diagnostics.FileVersionInfo.Forwards;_AssemblyInfo;System.Diagnostics.Process.Forwards;_AssemblyInfo;System.Diagnostics.StackTrace.Forwards;_AssemblyInfo;System.Diagnostics.TextWriterTraceListener.Forwards;_AssemblyInfo;System.Diagnostics.Tools.Forwards;_AssemblyInfo;System.Diagnostics.TraceSource.Forwards;_AssemblyInfo;System.Diagnostics.Tracing.Forwards;_AssemblyInfo;System.Drawing.Primitives.Forwards;_AssemblyInfo;System.Dynamic.Runtime.Forwards;_AssemblyInfo;System.Globalization.Calendars.Forwards;_AssemblyInfo;System.Globalization.Forwards;_AssemblyInfo;System.Globalization.Extensions.Forwards;_AssemblyInfo;System.IO.Compression.Forwards;_AssemblyInfo;System.IO.Compression.ZipFile.Forwards;_AssemblyInfo;System.IO.Forwards;_AssemblyInfo;System.IO.FileSystem.Forwards;_AssemblyInfo;System.IO.FileSystem.DriveInfo.Forwards;_AssemblyInfo;System.IO.FileSystem.Primitives.Forwards;_AssemblyInfo;System.IO.FileSystem.Watcher.Forwards;_AssemblyInfo;System.IO.IsolatedStorage.Forwards;_AssemblyInfo;System.IO.MemoryMappedFiles.Forwards;_AssemblyInfo;System.IO.Pipes.Forwards;_AssemblyInfo;System.IO.UnmanagedMemoryStream.Forwards;_AssemblyInfo;System.Linq.Forwards;_AssemblyInfo;System.Linq.Expressions.Forwards;_AssemblyInfo;System.Linq.Parallel.Forwards;_AssemblyInfo;System.Linq.Queryable.Forwards;_AssemblyInfo;System.Net.Http.Forwards;_AssemblyInfo;System.Net.NameResolution.Forwards;_AssemblyInfo;System.Net.NetworkInformation.Forwards;System.Net.NetworkInformation.manual;_AssemblyInfo;System.Net.Ping.Forwards;_AssemblyInfo;System.Net.Primitives.Forwards;_AssemblyInfo;System.Net.Requests.Forwards;_AssemblyInfo;System.Net.Security.Forwards;_AssemblyInfo;System.Net.Sockets.Forwards;_AssemblyInfo;System.Net.WebHeaderCollection.Forwards;_AssemblyInfo;System.Net.WebSockets.Client.Forwards;_AssemblyInfo;System.Net.WebSockets.Forwards;_AssemblyInfo;System.ObjectModel.Forwards;_AssemblyInfo;System.Reflection.Forwards;_AssemblyInfo;System.Reflection.Extensions.Forwards;_AssemblyInfo;System.Reflection.Primitives.Forwards;_AssemblyInfo;System.Resources.Reader.Forwards;_AssemblyInfo;System.Resources.ResourceManager.Forwards;_AssemblyInfo;System.Resources.Writer.Forwards;_AssemblyInfo;System.Runtime.CompilerServices.VisualC.Forwards;_AssemblyInfo;System.Runtime.Forwards;_AssemblyInfo;System.Runtime.Extensions.Forwards;_AssemblyInfo;System.Runtime.Handles.Forwards;_AssemblyInfo;System.Runtime.InteropServices.Forwards;_AssemblyInfo;System.Runtime.InteropServices.RuntimeInformation.Forwards;_AssemblyInfo;System.Runtime.Numerics.Forwards;_AssemblyInfo;System.Runtime.Serialization.Formatters.Forwards;_AssemblyInfo;System.Runtime.Serialization.Json.Forwards;_AssemblyInfo;System.Runtime.Serialization.Primitives.Forwards;_AssemblyInfo;System.Runtime.Serialization.Xml.Forwards;_AssemblyInfo;System.Security.Claims.Forwards;_AssemblyInfo;System.Security.Cryptography.Algorithms.Forwards;_AssemblyInfo;System.Security.Cryptography.Csp.Forwards;_AssemblyInfo;System.Security.Cryptography.Encoding.Forwards;_AssemblyInfo;System.Security.Cryptography.Primitives.Forwards;_AssemblyInfo;System.Security.Cryptography.X509Certificates.Forwards;_AssemblyInfo;System.Security.Principal.Forwards;_AssemblyInfo;System.Security.SecureString.Forwards;_AssemblyInfo;System.Text.Encoding.Forwards;_AssemblyInfo;System.Text.Encoding.Extensions.Forwards;_AssemblyInfo;System.Text.RegularExpressions.Forwards;_AssemblyInfo;System.Threading.Forwards;_AssemblyInfo;System.Threading.Overlapped.Forwards;_AssemblyInfo;System.Threading.Tasks.Forwards;_AssemblyInfo;System.Threading.Tasks.Parallel.Forwards;_AssemblyInfo;System.Threading.Thread.Forwards;_AssemblyInfo;System.Threading.ThreadPool.Forwards;_AssemblyInfo;System.Threading.Timer.Forwards;_AssemblyInfo;System.ValueTuple.Forwards;_AssemblyInfo;System.Xml.ReaderWriter.Forwards;_AssemblyInfo;System.Xml.XDocument.Forwards;_AssemblyInfo;System.Xml.XmlDocument.Forwards;_AssemblyInfo;System.Xml.XmlSerializer.Forwards;_AssemblyInfo;System.Xml.XPath.Forwards;_AssemblyInfo;System.Xml.XPath.XDocument.Forwards;_AssemblyInfo;mscorlib.Forwards;_AssemblyInfo;System.ComponentModel.Composition.Forwards;_AssemblyInfo;System.Core.Forwards;_AssemblyInfo;System.Forwards;_AssemblyInfo;System.Data.Forwards;_AssemblyInfo;System.Drawing.Forwards;_AssemblyInfo;System.IO.Compression.FileSystem.Forwards;_AssemblyInfo;System.Net.Forwards;_AssemblyInfo;System.Numerics.Forwards;_AssemblyInfo;System.Runtime.Serialization.Forwards;_AssemblyInfo;System.ServiceModel.Web.Forwards;_AssemblyInfo;System.Transactions.Forwards;_AssemblyInfo;System.Web.Forwards;_AssemblyInfo;System.Windows.Forwards;_AssemblyInfo;System.Xml.Forwards;_AssemblyInfo;System.Xml.Linq.Forwards;_AssemblyInfo;System.Xml.Serialization.Forwards;_AssemblyInfo">
      <Facade>true</Facade>
    </_NetStandardLibraryRefFile>
    <_NetStandardLibraryRef Include="@(_NetStandardLibraryRefFile->'$(MSBuildThisFileDirectory)\ref\%(Identity).dll')" />
  </ItemGroup>

  <!-- import the TFM-agnostic targets -->
  <Import Project="..\$(MSBuildThisFile)"/>
</Project>

Did you replace both? Replacing only one is invalid.

ericstj · 2017-09-20T19:54:53Z

Ping @davkean. Can you please confirm you tested replacing both files and that the references were still provided? (or share the msbuild or CLI so I can measure myself) If so that means my fix worked and we should take it.

davkean · 2017-09-20T22:21:09Z

Here's with your changes and all costs associated with NETStandard.Library.targets:

Pass	File	Line #	Expression	Inc (ms)	Inc (%)	Exc (ms)	Exc (%)	#
Total Evaluation				3800	100%	15	0.4%
Initial Properties (Pass 0)				19	0.5%	19	0.5%
Properties (Pass 1)				2409	63.4%	4	0.1%
ItemDefinitionGroup (Pass 2)				11	0.3%	1	0%
Items (Pass 3)				640	16.9%	12	0.3%
Lazy Items (Pass 3.1)				419	11%	126	3.3%
UsingTasks (Pass 4)				48	1.3%	48	1.3%
Targets (Pass 5)				238	6.3%	142	3.7%
Items (Pass 3)	NETStandard.Library.targets	11	`<_NetStandardLibraryRef Include="@(_NetStandardLibraryRefFile->'$(MSBuildThisFileDirectory)\ref\%...`	164	4.3%	147	3.9%	43
Lazy Items (Pass 3.1)	NETStandard.Library.targets	7	`<Reference Include="@(_NetStandardLibraryRef)" ><!-- Private = false to make these reference only --...`	81	2.1%	81	2.1%	43
Items (Pass 3)	NETStandard.Library.targets	8	`<_NetStandardLibraryRefFile Include="Microsoft.Win32.Primitives;Microsoft.Win32.Primitives;System.Ap...`	71	1.9%	71	1.9%	43
Items (Pass 3)	NETStandard.Library.targets	6	`Condition="'@(_NetStandardLibraryRef)' != ''")`	176	4.6%	13	0.3%	43
Properties (Pass 1)	NETStandard.Library.targets	6	`<PropertyGroup Condition="'$(TargetFrameworkIdentifier)' == '.NETStandarded'" ><_NetStandardLibraryR...`	3	0.1%	3	0.1%	126
Properties (Pass 1)	NETStandard.Library.targets	11	`<Import Project="..\$(MSBuildThisFile)" />`	3	0.1%	2	0%	126

These targets still own the top 3 expressions.

Is there a reason that these need to exist in evaluation?

davkean · 2017-09-20T22:36:32Z

Side note, I've pushed a branch containing Daniel and my changes: https://github.com/davkean/msbuild/tree/evaluation-performance-summary2. This is a hacked up build that will write a file called EvaluationTime.log after a build to the current directory.

Note - the evaluation calculation consumes time, so only the percentages themselves should be trusted timewise and you should use a single proc build (/m:1).

ericstj · 2017-09-20T23:20:31Z

Items (Pass 3) | NETStandard.Library.targets | 11 | <_NetStandardLibraryRef Include="@(_NetStandardLibraryRefFile->'$(MSBuildThisFileDirectory)\ref%... | 164 | 4.3% | 147 | 3.9% | 43

Am I reading this correctly that the item transformation is the highest cost? That seems really long for what should be string manipulation.

Items (Pass 3) | NETStandard.Library.targets | 6 | Condition="'@(_NetStandardLibraryRef)' != ''") | 176 | 4.6% | 13 | 0.3%

What's the difference between inclusive / exclusive here. It's just a condition how can it have any non-exclusive time?

Is there a reason that these need to exist in evaluation?

We need all those files to be passed as references. We could do it in a target instead if you think that'd be faster, but don't all the cases you're looking at require evaluation and some subset of RAR? That would need to run the target and incur the evaluation cost at that point.

danmoseley · 2017-09-20T23:58:38Z

I agree it is odd that what is essentially a little string manipulation is showing up in your profile. I wonder whether it is bracketing correctly.

For this Condition="'@(_NetStandardLibraryRef)' != ''") there is special casing to make sure it doesn't expand the items, but just checks whether there are any or not:

https://github.com/Microsoft/msbuild/blob/master/src/Build/Evaluation/Conditionals/MultipleComparisonExpressionNode.cs#L50

Perhaps that broke.

davkean · 2017-09-21T00:30:11Z

@ericstj TBH I'm not sure what's what Inc/Excl time is for the condition - my guess it that is the expansion of the item, let me check and debug this.

With regards to evaluation vs target cost - agreed, we want target cost to be minimal, however, if it lives in evaluation it's much worse from a performance standpoint:

We pay for evaluation inside VS while opening the project in CPS (evaluation takes up >50% of time to open a .NET Core project)
We pay for evaluation inside VS whenever there is a project change - this will block the UI if you adding/removing inside VS via Solution Explorer (in legacy this will also perform a design-time build)
We pay for evaluation twice for every project reference that a project has.

When a project has project references that are .NET Core/.NET Standard, evaluation of other project easily outweighs any cost that targets have. If we can push things to targets we pay for them less and calculate them less. Currently, we're paying for those above items just to figure out what the TFM is of the project when walking references.

davkean · 2017-09-21T04:57:55Z

~~Debugging this looks like the <Reference/> nested in the is being incorrectly contributed to the condition - need to figure out why we're doing that~~. Side note, I did cut the condition itself by a 3rd (from 0.3% -> 0.1%) by remembering in MultipleComparisonExpressionNode.cs whether it evaluated to empty.

davkean · 2017-09-21T06:24:38Z

My mistake, was reading the debugging wrong - basically, yes, my first guess was correct - to order to figure out if the expression evaluates to empty in the following:

<ItemGroup Condition="'@(_NetStandardLibraryRef)' != ''">
...
</ItemGroup>

It needs to evaluate:

<ItemGroup>
...
   <_NetStandardLibraryRef Include="@(_NetStandardLibraryRefFile->'$(MSBuildThisFileDirectory)\ref\%(Identity).dll')" />
</ItemGroup>

 	Microsoft.Build.dll!Microsoft.Build.Evaluation.LazyItemEvaluator<Microsoft.Build.Execution.ProjectPropertyInstance, Microsoft.Build.Execution.ProjectItemInstance, Microsoft.Build.Execution.ProjectMetadataInstance, Microsoft.Build.Execution.ProjectItemDefinitionInstance>.LazyItemOperation.Apply(System.Collections.Immutable.ImmutableList<Microsoft.Build.Evaluation.LazyItemEvaluator<Microsoft.Build.Execution.ProjectPropertyInstance, Microsoft.Build.Execution.ProjectItemInstance, Microsoft.Build.Execution.ProjectMetadataInstance, Microsoft.Build.Execution.ProjectItemDefinitionInstance>.ItemData>.Builder listBuilder, System.Collections.Immutable.ImmutableHashSet<string> globsToIgnore) Line 54	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.Evaluation.LazyItemEvaluator<Microsoft.Build.Execution.ProjectPropertyInstance, Microsoft.Build.Execution.ProjectItemInstance, Microsoft.Build.Execution.ProjectMetadataInstance, Microsoft.Build.Execution.ProjectItemDefinitionInstance>.MemoizedOperation.Apply(System.Collections.Immutable.ImmutableList<Microsoft.Build.Evaluation.LazyItemEvaluator<Microsoft.Build.Execution.ProjectPropertyInstance, Microsoft.Build.Execution.ProjectItemInstance, Microsoft.Build.Execution.ProjectMetadataInstance, Microsoft.Build.Execution.ProjectItemDefinitionInstance>.ItemData>.Builder listBuilder, System.Collections.Immutable.ImmutableHashSet<string> globsToIgnore) Line 172	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.Evaluation.LazyItemEvaluator<Microsoft.Build.Execution.ProjectPropertyInstance, Microsoft.Build.Execution.ProjectItemInstance, Microsoft.Build.Execution.ProjectMetadataInstance, Microsoft.Build.Execution.ProjectItemDefinitionInstance>.LazyItemList.ComputeItems(Microsoft.Build.Evaluation.LazyItemEvaluator<Microsoft.Build.Execution.ProjectPropertyInstance, Microsoft.Build.Execution.ProjectItemInstance, Microsoft.Build.Execution.ProjectMetadataInstance, Microsoft.Build.Execution.ProjectItemDefinitionInstance>.LazyItemList lazyItemList, System.Collections.Immutable.ImmutableHashSet<string> globsToIgnore) Line 353	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.Evaluation.LazyItemEvaluator<Microsoft.Build.Execution.ProjectPropertyInstance, Microsoft.Build.Execution.ProjectItemInstance, Microsoft.Build.Execution.ProjectMetadataInstance, Microsoft.Build.Execution.ProjectItemDefinitionInstance>.LazyItemList.GetItems(System.Collections.Immutable.ImmutableHashSet<string> globsToIgnore) Line 282	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.Evaluation.LazyItemEvaluator<Microsoft.Build.Execution.ProjectPropertyInstance, Microsoft.Build.Execution.ProjectItemInstance, Microsoft.Build.Execution.ProjectMetadataInstance, Microsoft.Build.Execution.ProjectItemDefinitionInstance>.GetItems(string itemType) Line 68	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.Evaluation.LazyItemEvaluator<Microsoft.Build.Execution.ProjectPropertyInstance, Microsoft.Build.Execution.ProjectItemInstance, Microsoft.Build.Execution.ProjectMetadataInstance, Microsoft.Build.Execution.ProjectItemDefinitionInstance>..ctor.AnonymousMethod__10_0(string itemType) Line 54	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.Evaluation.LazyItemEvaluator<Microsoft.Build.Execution.ProjectPropertyInstance, Microsoft.Build.Execution.ProjectItemInstance, Microsoft.Build.Execution.ProjectMetadataInstance, Microsoft.Build.Execution.ProjectItemDefinitionInstance>.EvaluatorData.GetItems(string itemType) Line 44	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.Evaluation.Expander<Microsoft.Build.Execution.ProjectPropertyInstance, Microsoft.Build.Execution.ProjectItemInstance>.ItemExpander.ExpandExpressionCapture<Microsoft.Build.Execution.ProjectItemInstance>(Microsoft.Build.Evaluation.Expander<Microsoft.Build.Execution.ProjectPropertyInstance, Microsoft.Build.Execution.ProjectItemInstance> expander, Microsoft.Build.Evaluation.ExpressionShredder.ItemExpressionCapture expressionCapture, Microsoft.Build.Evaluation.IItemProvider<Microsoft.Build.Execution.ProjectItemInstance> evaluatedItems, Microsoft.Build.Shared.IElementLocation elementLocation, Microsoft.Build.Evaluation.ExpanderOptions options, bool includeNullEntries, out bool isTransformExpression, out System.Collections.Generic.List<System.Tuple<string, Microsoft.Build.Execution.ProjectItemInstance>> itemsFromCapture) Line 1776	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.Evaluation.Expander<Microsoft.Build.Execution.ProjectPropertyInstance, Microsoft.Build.Execution.ProjectItemInstance>.ItemExpander.ExpandExpressionCaptureIntoStringBuilder<Microsoft.Build.Execution.ProjectItemInstance>(Microsoft.Build.Evaluation.Expander<Microsoft.Build.Execution.ProjectPropertyInstance, Microsoft.Build.Execution.ProjectItemInstance> expander, Microsoft.Build.Evaluation.ExpressionShredder.ItemExpressionCapture capture, Microsoft.Build.Evaluation.IItemProvider<Microsoft.Build.Execution.ProjectItemInstance> evaluatedItems, Microsoft.Build.Shared.IElementLocation elementLocation, Microsoft.Build.Shared.ReuseableStringBuilder builder, Microsoft.Build.Evaluation.ExpanderOptions options) Line 1953	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.Evaluation.Expander<Microsoft.Build.Execution.ProjectPropertyInstance, Microsoft.Build.Execution.ProjectItemInstance>.ItemExpander.ExpandItemVectorsIntoString<Microsoft.Build.Execution.ProjectItemInstance>(Microsoft.Build.Evaluation.Expander<Microsoft.Build.Execution.ProjectPropertyInstance, Microsoft.Build.Execution.ProjectItemInstance> expander, string expression, Microsoft.Build.Evaluation.IItemProvider<Microsoft.Build.Execution.ProjectItemInstance> items, Microsoft.Build.Evaluation.ExpanderOptions options, Microsoft.Build.Shared.IElementLocation elementLocation) Line 1877	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.Evaluation.Expander<Microsoft.Build.Execution.ProjectPropertyInstance, Microsoft.Build.Execution.ProjectItemInstance>.ExpandIntoStringLeaveEscaped(string expression, Microsoft.Build.Evaluation.ExpanderOptions options, Microsoft.Build.Shared.IElementLocation elementLocation) Line 266	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.Evaluation.Expander<Microsoft.Build.Execution.ProjectPropertyInstance, Microsoft.Build.Execution.ProjectItemInstance>.ExpandIntoStringAndUnescape(string expression, Microsoft.Build.Evaluation.ExpanderOptions options, Microsoft.Build.Shared.IElementLocation elementLocation) Line 241	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.Evaluation.ConditionEvaluator.ConditionEvaluationState<Microsoft.Build.Execution.ProjectPropertyInstance, Microsoft.Build.Execution.ProjectItemInstance>.ExpandIntoStringBreakEarly(string expression) Line 459	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.Evaluation.StringExpressionNode.EvaluatesToEmpty(Microsoft.Build.Evaluation.ConditionEvaluator.IConditionEvaluationState state) Line 83	C#	Symbols loaded.
>	Microsoft.Build.dll!Microsoft.Build.Evaluation.MultipleComparisonNode.BoolEvaluate(Microsoft.Build.Evaluation.ConditionEvaluator.IConditionEvaluationState state) Line 57	C#	Symbols loaded.

I wonder if this regressed when lazy items were introduced @dsplaisted @cdmihai?

davkean · 2017-09-21T06:34:37Z

But if the expression is remembered via the lazy evaluator does it matter? You need to pay for it at some point, right?

davkean · 2017-09-21T07:15:02Z

Did a quick test of doing a build on an empty project with just this expression in a project, I see 14% of CPU here:

dsplaisted · 2017-09-21T19:07:56Z

But if the expression is remembered via the lazy evaluator does it matter? You need to pay for it at some point, right?

Yes, the _NetStandardLibraryRef item will need to be evaluated eventually, it just happens that the '@(_NetStandardLibraryRef)' != '' condition is what does it first.

So the condition is incidental, it looks like we should be focusing on making this faster:

<_NetStandardLibraryRef Include="@(_NetStandardLibraryRefFile->'$(MSBuildThisFileDirectory)\ref\%(Identity).dll')" />

Either by changing the form of the expression (perhaps statically listing the items instead of using a transformation would be better), or by optimizing how MSBuild evaluates this expression.

ericstj · 2017-09-21T20:59:54Z

I can try it, but I've already got a static list (note it is also appearing in top hits above). My gut feel is that the existing transform that is doing string concatenation ought to be a lot faster than bloating the file with repeated full paths that need to be parsed and evaluated.

davkean · 2017-09-21T21:05:21Z

I wouldn't make that assumption, it runs a regex over it and does a bunch of other work.

davkean · 2017-09-22T00:38:24Z

@ericstj I tried looking to see where the cost is here - and there's no clear low hanging fruit, and don't have enough context to be fruitful here. From what I can see cost is a variety of things:

Getting metadata
Running a regex
String concat that occurs

This is what I'd like to see:

Push this code off into a target. I still don't understand if/how the dependency node picks this up - so unclear if that will break that.
Least see if the static list is at least faster

I've pushed the branch above if you'd try out the profiler yourself. I'm happy to continue to test this for you but bear in mind there will be a lag time as I'm focusing on other stuff.

ericstj · 2017-09-22T15:22:53Z

I grabbed your branch and will try it. I plan to get it running as a baseline, then refactor the targets a bit to use optimize the syntax, then try moving to a target (and hopefully keep whatever improvements I got from the optimization). FWIW I was testing before with this stuff in a target for measurement purposes and I wasn't seeing much difference between wild-card and static list using the existing target duration PerformanceSummary method.

ericstj · 2017-09-22T19:08:54Z

I've played around with this and got us completely off the radar without moving anything to targets. It turns out chaining items together and transforming all have a significant cost when you're doing it on 100+ items with lots of metadata. My final solution was to generate full path lists and directly add them to the reference item and never try to evaluate any of the items I was building up.

See my measurements along the way here: https://gist.github.com/ericstj/182e563d3efc58bd8d11bac6f518cc80

EvaluationTime.original - the original shipping implementation.
EvaluationTime.fileNameList - the proposed fix that writes all the names to the targets (avoiding the wildcard) but still transforms those into paths, then evaluates the item for empty when setting Reference, and copies into Reference.
EvaluationTime.filePathList - avoids the transformation from 2 by repeating the path.
EvaluationTime.filePathList.singleTargetsFile - avoids the empty evaluation from 2/3 by combining the two targets files and using the single property condition.
EvaluationTime.filePathList.singleItem - avoids the item copy from 2/3/4 by directly setting the reference item.

I'll submit a PR to take this change as it seems to have resolved the issue (given this measurement). Its still possible that we pay for those items somewhere so I'd like for folks to try out my change.

davkean · 2017-09-25T00:33:06Z

Thanks!

davkean · 2017-09-26T01:11:03Z

This was resolved in #507.

ericstj · 2017-09-26T17:40:04Z

Reopening to track bringing this in for servicing.

ericstj · 2017-09-26T21:05:25Z

Closing now as it has been accepted and merged in servicing.

davkean mentioned this issue Aug 15, 2017

UI delays when mixing legacy and CPS based projects dotnet/project-system#2712

Closed

davkean changed the title ~~Adding .NET Standard reference assemblies is consuming 4% CPU time of a build~~ Adding .NET Standard reference assemblies is consuming 20% of a single design-time build, 9% of a solution design-time build Aug 16, 2017

weshaggard assigned ericstj Aug 18, 2017

davkean mentioned this issue Sep 6, 2017

.NET Core/.NET Standard build performance dotnet/project-system#2789

Closed

davkean mentioned this issue Sep 14, 2017

[Tracking] Overhead of evaluation is too high for design-time builds dotnet/sdk#1586

Closed

davkean changed the title ~~Adding .NET Standard reference assemblies is consuming 20% of a single design-time build, 9% of a solution design-time build~~ Adding .NET Standard/.NET Framework facades assemblies is consuming 11% of build time Sep 14, 2017

ericstj mentioned this issue Sep 14, 2017

Calculating whether a .NET Standard library ref is a facade costs 0.5% of solution-wide design time build #494

Closed

ericstj mentioned this issue Sep 22, 2017

Use a file list rather than globbing NETStandard assemblies #507

Merged

davkean closed this as completed Sep 26, 2017

ericstj reopened this Sep 26, 2017

ericstj closed this as completed Sep 26, 2017

This was referenced Oct 24, 2017

Table is shown instead of code k0shk0sh/FastHub#1179

Closed

Table is shown instead of code k0shk0sh/FastHub#1180

Closed

weshaggard mentioned this issue Apr 5, 2018

Stabalize 2.0.2 NETStandard.Library package #701

Merged

Adding .NET Standard/.NET Framework facades assemblies is consuming 11% of build time #442

Adding .NET Standard/.NET Framework facades assemblies is consuming 11% of build time #442

Comments

davkean commented Aug 15, 2017 • edited Loading

davkean commented Aug 15, 2017 • edited Loading

davkean commented Aug 16, 2017

ericstj commented Aug 31, 2017 • edited Loading

davkean commented Sep 1, 2017 • edited Loading

davkean commented Sep 1, 2017 • edited Loading

ericstj commented Sep 7, 2017

ericstj commented Sep 8, 2017 • edited Loading

ericstj commented Sep 8, 2017 • edited Loading

davkean commented Sep 13, 2017 • edited Loading

davkean commented Sep 13, 2017 • edited Loading

ericstj commented Sep 13, 2017 • edited Loading

davkean commented Sep 14, 2017 • edited Loading

davkean commented Sep 14, 2017

davkean commented Sep 14, 2017

ericstj commented Sep 14, 2017

davkean commented Sep 14, 2017 via email • edited Loading

davkean commented Sep 19, 2017

Before

After

ericstj commented Sep 19, 2017 • edited Loading

ericstj commented Sep 20, 2017

davkean commented Sep 20, 2017

davkean commented Sep 20, 2017 • edited Loading

ericstj commented Sep 20, 2017

danmoseley commented Sep 20, 2017

davkean commented Sep 21, 2017 • edited Loading

davkean commented Sep 21, 2017 • edited Loading

davkean commented Sep 21, 2017 • edited Loading

davkean commented Sep 21, 2017

davkean commented Sep 21, 2017

dsplaisted commented Sep 21, 2017

ericstj commented Sep 21, 2017

davkean commented Sep 21, 2017 via email • edited Loading

davkean commented Sep 22, 2017 • edited Loading

ericstj commented Sep 22, 2017

ericstj commented Sep 22, 2017

davkean commented Sep 25, 2017

davkean commented Sep 26, 2017

ericstj commented Sep 26, 2017

ericstj commented Sep 26, 2017

davkean commented Aug 15, 2017 •

edited

Loading

davkean commented Aug 15, 2017 •

edited

Loading

ericstj commented Aug 31, 2017 •

edited

Loading

davkean commented Sep 1, 2017 •

edited

Loading

davkean commented Sep 1, 2017 •

edited

Loading

ericstj commented Sep 8, 2017 •

edited

Loading

ericstj commented Sep 8, 2017 •

edited

Loading

davkean commented Sep 13, 2017 •

edited

Loading

davkean commented Sep 13, 2017 •

edited

Loading

ericstj commented Sep 13, 2017 •

edited

Loading

davkean commented Sep 14, 2017 •

edited

Loading

davkean commented Sep 14, 2017 via email •

edited

Loading

ericstj commented Sep 19, 2017 •

edited

Loading

davkean commented Sep 20, 2017 •

edited

Loading

davkean commented Sep 21, 2017 •

edited

Loading

davkean commented Sep 21, 2017 •

edited

Loading

davkean commented Sep 21, 2017 •

edited

Loading

davkean commented Sep 21, 2017 via email •

edited

Loading

davkean commented Sep 22, 2017 •

edited

Loading