Speed up incremental package asset resolution #2020

nguerrera · 2018-03-05T01:55:53Z

Whenever project.assets.json changes (or more rarely, a setting influencing ResolvePackageAssets changes), write out a binary cache file for the next incremental build. The file has only the items that used by the build and they are written in a format that can be deserialized to MSBuild ITaskItem[] with minimal time and allocation.

On top of that, we merge ReportAssetsLogMessages into ResolvePackageAssets, which allows for project.assets.json to not be read at all if it has not changed.

Some early measurement below using https://github.com/mikeharder/dotnet-cli-perf/tree/master/scenarios/web/large/core

First observation, the total size of all assets.cache files is 5 MB vs. 37 MB for assets.json.

I will send a private drop to our internal perf alias as wll.

Incremental build --no-restore /m:1

Before 
      161 ms  JoinItems                                129 calls
      176 ms  AssignProjectConfiguration               129 calls
      264 ms  Copy                                     370 calls
      318 ms  ResolvePackageFileConflicts              129 calls
     1180 ms  ReportAssetsLogMessages                  129 calls
     2873 ms  ResolvePackageAssets                     129 calls
    23138 ms  ResolveAssemblyReference                 129 calls
    
    Time Elapsed 00:00:40.08
    
After
      117 ms  JoinItems                                129 calls
      127 ms  GetReferenceNearestTargetFrameworkTask   109 calls
      136 ms  AssignProjectConfiguration               129 calls
      150 ms  Message                                  388 calls
      252 ms  ResolvePackageAssets                     129 calls
      257 ms  ResolvePackageFileConflicts              129 calls
      307 ms  Copy                                     370 calls
    23261 ms  ResolveAssemblyReference                 129 calls

    Time Elapsed 00:00:36.04

Saving 10% overall here and reducing ResolvePackageAssets+ReportAssetsLogMessage (now combined into ResolvePackageAssets) from ~4 seconds to ~250 milliseconds.

Incremental parallel build --no-restore

Before
      184 ms  Hash                                     258 calls
      232 ms  JoinItems                                129 calls
      240 ms  GetReferenceNearestTargetFrameworkTask   109 calls
      299 ms  AssignProjectConfiguration               129 calls
      487 ms  ResolvePackageFileConflicts              129 calls
      492 ms  Copy                                     370 calls
     2654 ms  ReportAssetsLogMessages                  129 calls
     5071 ms  ResolvePackageAssets                     129 calls
    37575 ms  ResolveAssemblyReference                 129 calls
    
    Time Elapsed 00:00:19.72

After
      100 ms  ConvertToAbsolutePath                    129 calls
      116 ms  ProduceContentAssets                     129 calls
      157 ms  FindUnderPath                            645 calls
      185 ms  Hash                                     258 calls
      246 ms  JoinItems                                129 calls
      329 ms  AssignProjectConfiguration               129 calls
      447 ms  GetReferenceNearestTargetFrameworkTask   109 calls
      487 ms  ResolvePackageFileConflicts              129 calls
      502 ms  Copy                                     370 calls
      612 ms  ResolvePackageAssets                     129 calls
    38504 ms  ResolveAssemblyReference                 129 calls

    Time Elapsed 00:00:18.54

Overall saving is less in parallel case, but time in (ResolvePackageAssets + ReportAssetsLogMessage) goes down from ~7.5 seconds to ~ 600 milliseconds.

It is interesting that just about every task is taking significantly more cumulative time when building in parallel. But, of course, some (most???) of the 7 seconds difference is being recuperated by parallelism.

Clean parallel build --no-restore (cleaned and restored beforehand)

Before
      168 ms  Hash                                     258 calls
      270 ms  GetReferenceNearestTargetFrameworkTask   109 calls
      301 ms  JoinItems                                129 calls
      306 ms  MakeDir                                  129 calls
      333 ms  AssignProjectConfiguration               129 calls
      524 ms  ResolvePackageFileConflicts              129 calls
      559 ms  WriteCodeFragment                        129 calls
     1866 ms  WriteLinesToFile                         387 calls
     3268 ms  ReportAssetsLogMessages                  129 calls
     4616 ms  GenerateDepsFile                         129 calls
     5577 ms  ResolvePackageAssets                     129 calls
     6945 ms  Copy                                     370 calls
    24787 ms  Csc                                      129 calls
    41201 ms  ResolveAssemblyReference                 129 calls
    
    Time Elapsed 00:00:29.46
    
After
      167 ms  Hash                                     258 calls
      181 ms  FindUnderPath                            645 calls
      234 ms  GetReferenceNearestTargetFrameworkTask   109 calls
      270 ms  AssignProjectConfiguration               129 calls
      294 ms  JoinItems                                129 calls
      299 ms  MakeDir                                  129 calls
      487 ms  ResolvePackageFileConflicts              129 calls
      540 ms  WriteCodeFragment                        129 calls
     1501 ms  WriteLinesToFile                         387 calls
     4317 ms  GenerateDepsFile                         129 calls
     6802 ms  Copy                                     370 calls
     9715 ms  ResolvePackageAssets                     129 calls
    26625 ms  Csc                                      129 calls
    39653 ms  ResolveAssemblyReference                 129 calls
    
    Time Elapsed 00:00:30.44

This case shows the slowdown of (ResolvePackageAssets + ReportAssetsLogMessage) from ~8.8 seconds to ~9.7 seconds in the first run of ResolvePackageAssets where the cache needs to be generated. I have some ideas on how to narrow this down significantly, but note that it does not impact the inner loop case where project.assets.json would not be changing between every build.

cc @mikeharder @davkean @livarcocc @dsplaisted

Whenever project.assets.json changes (or more rarely, a setting influencing ResolvePackageAssets changes), write out a binary cache file for the next incremental build. The file has only the items that used by the build and they are written in a format that can be deserialized to MSBuild ITaskItem[] with minimal time and allocation.

nguerrera · 2018-03-05T02:02:47Z

Related: #1711 (resolves it for normal builds, more work to do for dependencies node / design-time build)_

davkean · 2018-03-05T02:03:36Z

src/Tasks/Microsoft.NET.Build.Tasks/ResolvePackageAssets.cs

                    }
+                }


It doesn't look like you handle InvalidDataException here - I would have thought we'd want to throw away the cache in that case?

InvalidDataException doesn't derive from IOException - which you may have thought it did.

Good catch. Need to add tests for this. I did think it derived from IOException.

Fixed and test coverage added.

davkean · 2018-03-05T02:04:59Z

src/Tasks/Microsoft.NET.Build.Tasks/ResolvePackageAssets.cs

+            private static BinaryReader OpenCacheFile(string path, byte[] settingsHash)
+            {
+                var stream = File.Open(path, FileMode.Open, FileAccess.Read, FileShare.Read);
+                var reader = new BinaryReader(stream, TextEncoding, leaveOpen: false);


Why isn't this just a using?

Because we want to keep the reader open for the caller to own unless the header is out-of-date.

davkean

This is great, awesome effort.

livarcocc · 2018-03-05T18:59:30Z

src/Tasks/Microsoft.NET.Build.Tasks/ResolvePackageAssets.cs

+                _bufferedMetadata = new List<int>();
+
+                Directory.CreateDirectory(Path.GetDirectoryName(task.ProjectAssetsCacheFile));
+                var stream = File.Open(task.ProjectAssetsCacheFile, FileMode.Create, FileAccess.ReadWrite, FileShare.None);


Do you need to worry about concurrent writes here? I see you have None there, but if it happens, will this bubble up? Is that what you intend?

The cache file is in Intermediate directory, and has msbuildprojectname in it. If we double write here, project configuration is busted. We'd double write a bunch of other stuff too.

Sounds good.

livarcocc · 2018-03-05T19:25:17Z

src/Tasks/Microsoft.NET.Build.Tasks/ResolvePackageAssets.cs

+
+            private void WriteItemGroups()
+            {
+                // NOTE: Order (alphabetical by group name) must match writer.


Did you mean must match reader?

Yes copy paste error. Thanks

mikeharder · 2018-03-06T04:05:49Z

My results are similar to @nguerrera:

Parallel	Core @ 8293	Core @ 8293 + ResolvePackageAssets	Delta	Delta %
1	52.8	48.8	4.0	7.6%
8	22.6	22.1	0.5	2.0%

The improvement is significantly larger for a single-proc build, even on a relative basis.

nguerrera · 2018-03-06T04:11:48Z

The symptom that every task is slower in parallel builds is reminiscent of the logging bug. We should check that it hasn't regressed. It's very strange to me that all that cumulative time in ResolvePackageAssets (and ReportAssetsLogMessages) is gone but only such a small fraction of those savings accrue to elapsed time.

mikeharder · 2018-03-06T06:20:46Z

I agree we should do more investigation of the relative performance between /m:1 and /m:8 (for an 8-core machine). The solution has 129 projects, and most of the "layers" in the dependency graph have at least 8 projects, so I would expect it to parallelize quite well. However, /m:8 is only about 2x faster than /m:1, compared to a theoretical maximum of 8x faster.

We should look at things like:

How is the work scheduled across the 8 nodes? Is a lot of time spent waiting?
What is the overall CPU utilization?
What is the cost of sending data between nodes (including serialization)?

CC: @rainersigwald

rainersigwald · 2018-03-06T06:54:47Z

Took a quick look at the /detailedsummary output of an /m:8 no-op incremental build on sdk 2.1.100 (msbuild 15.6.82.30579)

Utilization:          37.9    47.2    86.3    43.0    31.7    83.1    84.3    82.3     Average Utilization: 62.0

That's definitely not great, but I'd expect it to do better than a 2x speedup.

Looks like the node builds are densely packed for the first 44 seconds of the build and only then does the utilization graph start to have holes.

Definitely deserves a deeper look.

nguerrera · 2018-03-08T22:49:53Z

@dsplaisted Would you mind reviewing this one as well?

dsplaisted

It seems like it could be a good idea to have unit-level tests for reading and writing the cache file.

dsplaisted · 2018-03-12T21:07:39Z

src/Tasks/Common/DiagnosticsHelper.cs

@@ -59,58 +53,7 @@ public DiagnosticsHelper(ILog log)

            _diagnosticMessages.Add(diagnostic);

-            if (logToMSBuild)


Shouldn't you delete the logToMSBuild parameter to this method if you're removing the functionality?

dsplaisted · 2018-03-12T21:13:03Z

src/Tasks/Microsoft.NET.Build.Tasks/ReportAssetsLogMessages.cs

-    /// dependency node in the solution explorer)
+    /// Raise log messages in the assets file as DiagnosticMessage items
+    /// that can be consumed downstream (e.g. by the dependency node in
+    /// the solution explorer)
    /// </summary>
    public sealed class ReportAssetsLogMessages : TaskBase


Should this task be deleted entirely? Based on this comment, I would think so:

On top of that, we merge ReportAssetsLogMessages into ResolvePackageAssets, which allows for project.assets.json to not be read at all if it has not changed.

No. It is still used at design-time to add the diagnostics to nodes in the dependencies tree in the IDE. The old ResolvePackageDependencies is in the same boat...

It's next on the list to look at speeding up the depenencies node, but in the meantime, this has to stay.

Can we just use the ResolvePackageAssets task to load the log messages for the designer, so we get the benefits of caching?

Yes, but I'm leaving the design-time changes out of this PR as much as possible. The messages are the least of your worries there right now. I'd rather tackle the whole design-time resolution together.

#1711 is what I'm leaving open to tie up the loose ends in the design time case.

dsplaisted · 2018-03-12T21:15:58Z

src/Tasks/Microsoft.NET.Build.Tasks/targets/Microsoft.PackageDependencyResolution.targets

@@ -26,6 +26,7 @@ Copyright (c) .NET Foundation. All rights reserved.
  <!-- Project Assets File -->
  <PropertyGroup>
    <ProjectAssetsFile Condition="'$(ProjectAssetsFile)' == ''">$(BaseIntermediateOutputPath)/project.assets.json</ProjectAssetsFile>
+    <ProjectAssetsCacheFile Condition="'$(ProjectAssetsCacheFile)' == ''">$(IntermediateOutputPath)$(MSBuildProjectName).assets.cache</ProjectAssetsCacheFile>


Can we base this on Path.GetDirectoryName($(ProjectAssetsFile)) instead of hard coding the IntermediateOutputPath? This will work better with changes we are working on to use MSBuildExtensionsPath more consistently (NuGet/NuGet.Client#2056).

No. It is vital that we use a path that is unique to the current TFM (and to a lesser extent the current configuration). Each TFM caches the assets for that TFM and only that TFM. The assets file can move around to wherever it wants and this file can stay in the IntermediateOutputPath, so there's no maintenance issue. I can add a clarifying comment.

I had mistaken IntermediateOutputPath for BaseIntermediateOutputPath in the line you added. Now it makes sense.

I added a clarifying comment.

dsplaisted · 2018-03-12T21:16:41Z

src/Tasks/Microsoft.NET.Build.Tasks/ResolvePackageAssets.cs

        [Required]
        public string ProjectAssetsFile { get; set; }

+        /// <summary>
+        /// Path to assets.cache file in intermediate directory.


This should be next to the project.assets.json file, but not necessarily in the intermediate directory.

No. See above.

I will remove intermediate directory from this comment. It's the path to the cache file. The targets choose the location (but they need to pick a safe per-TFM, per-Configuration location).

dsplaisted · 2018-03-12T21:24:32Z

src/Tasks/Microsoft.NET.Build.Tasks/ResolvePackageAssets.cs


+        /// <summary>
+        /// Indicate to MSBuild ResolveAssemblyReferences that 


Incomplete comment here.

dsplaisted · 2018-03-12T21:54:57Z

src/Tasks/Microsoft.NET.Build.Tasks/ResolvePackageAssets.cs

+
+                for (int i = 0; i < metadataCount; i++)
+                {
+                    string key = _metadataStringTable[_reader.ReadInt32()];


Do you think it's worth throwing something better than an IndexOutOfRangeException if the index is wrong here? Should we try to throw an exception saying the assets file cache appears to be corrupt in cases like this?

This may be worth defending against. I will file a bug.

Filed #2049

dsplaisted · 2018-03-12T23:29:46Z

src/Tasks/Microsoft.NET.Build.Tasks/ResolvePackageAssets.cs

-        }
+            private void WriteItem(string itemSpec)
+            {
+                FlushMetadata();


It seems like it would be quite easy to end up writing the metadata out of order, since metadata is flushed before an item is written instead of afterwards. What's the reason for buffering the metadata items anyway? Would it be more straightforward to have WriteMetadata write directly to the stream, and in WriteItems call the writeMetadata callback after the call to WriteItem?

The reason for buffering is because we don't know how many metadata items will be written and we need to prepend the count. We have the same problem for items but there we write a placeholder and seek back to set the count. Seeking costs flushing the file stream buffer, though so we don't want to do that for every item. I was trying hard to avoid allocations in the writer so as not to over-penalize the first, uncached build. I will give some thought to how to improve this, but I won't hold on this for the initial PR.

As discussed offline another approach to this would have been to make the first run go from assets.json to ITaskItems directly (as before), but also write out the cache file for the incremental builds and incremental builds alone to use. The main reason why I did not write it that way was to make it so that full builds and incremental builds get the items from the same code so that there won't be mysterious bugs that only show up on incremental builds. This means that the entire test suite is stressing the cache reading/writing now.

There is potential to improve the readability of the code and the performance of the first build here, but I am reluctant to tackle that and reset the preview2 measurements that have been taken with this approach, nor do I want to lose the coverage property.

Filed #2048 to think about changing the approach.

dsplaisted · 2018-03-12T23:35:21Z

src/Tasks/Microsoft.NET.Build.Tasks/ResolvePackageAssets.cs

                    {
-                        if (!asset.IsPlaceholderFile() && (filter == null || filter(asset)))
+                        if (!NuGetUtils.IsApplicableAnalyzer(file, _task.ProjectLanguage))


This class combines two things: Logic for how we interpret the contents of the lock file, and the format we use to cache it. It seems like it would be cleaner to separate these two things into two different classes. Is this possible, or do they need to be mixed in order to maintain the perf gains from the cache?

They are mixed but the methods should be reasonably separated enough. This was indeed for perf so that we don't end up with any intermediate data to allocate when going from assets.json -> assets.cache.

This is covered by #2048. See #2020 (comment)

dsplaisted · 2018-03-12T23:36:47Z

src/Tasks/Microsoft.NET.Build.Tasks/ResolvePackageAssets.cs

-                p => p.ContentFiles,
-                filter: asset => !string.IsNullOrEmpty(asset.PPOutputPath),
-                setup: (asset, item) => 
+        private byte[] HashSettings()


Do we have any way of helping to keep this method up to date, so that whenever there is a property that would affect the result we make sure to add it to the hash?

I've added test coverage for that in 7b0dbb0

There was actually a bug that this fixes: if $(ProjectAssetsFile) or $(ProjectAssetsCacheFile) were to change between builds, we might consider a cache from a different assets file to be useable.

This would also have been easy to get wrong over time, so the test is definitely valuable. Great feedback!

dsplaisted · 2018-03-12T23:40:20Z

src/Tests/Microsoft.NET.Build.Tests/GivenThatWeWantBuildsToBeIncremental.cs

+            File.SetLastWriteTimeUtc(assetsJsonPath, DateTime.UtcNow);
+            buildCommand.Execute().Should().Pass();
+            var cacheWriteTime3 = File.GetLastWriteTimeUtc(assetsCachePath);
+            cacheWriteTime3.Should().NotBe(cacheWriteTime2);


Is it possible that a build would run fast enough that these times are actually the same? Should the test do a short sleep if DateTime.UtcNow hasn't increased at each stage?

…being too low

nguerrera · 2018-03-15T20:54:11Z

It seems like it could be a good idea to have unit-level tests for reading and writing the cache file.

It certainly wouldn't hurt, but as noted elsewhere every single integration test in the suite is going to be writing/reading from the cache. In fact, it is designed to go through the same path in full builds as incremental builds for exactly that reason. I noted in #2048 that if we take a different approach we will need much more testing for the incremental case.

nguerrera · 2018-03-16T00:14:29Z

@dotnet-bot Test OSX10.12 Debug

Filed #2052

The flakiness predates this change. I'm disabling the test on OS X if it fails again.

nguerrera requested review from dsplaisted, livarcocc and a team March 5, 2018 01:55

davkean reviewed Mar 5, 2018

View reviewed changes

nguerrera mentioned this pull request Mar 5, 2018

ResolvePackageDependencies is producing 6.5% of allocations in a build #1711

Closed

davkean reviewed Mar 5, 2018

View reviewed changes

davkean approved these changes Mar 5, 2018

View reviewed changes

livarcocc added this to the 2.1.3xx milestone Mar 5, 2018

livarcocc reviewed Mar 5, 2018

View reviewed changes

livarcocc approved these changes Mar 5, 2018

View reviewed changes

nguerrera added 3 commits March 7, 2018 16:21

Use PrepareForBuild to ensure intermediate directory creation

2298076

Fix unhandled exception in settings changed case and add test

2583e4c

Fix copy/paste error in comment

84de38b

dsplaisted approved these changes Mar 12, 2018

View reviewed changes

nguerrera added 6 commits March 13, 2018 11:43

PR feedback: remove unused logToMSBuild parameter

e726e66

PR feedback: clarify assets.cache file location in comments

f34b764

PR feedback: Defend against tests running too fast

5109c9c

PR feedback: clarify comments

e685a1a

PR feedback: use test to ensure that all task parameters are hashed

7b0dbb0

PR feedback: handle theoretical risk of modification time resolution …

1ced039

…being too low

nguerrera mentioned this pull request Mar 15, 2018

Harden against corrupt assets.cache file #2049

Open

nguerrera added 2 commits March 15, 2018 14:25

PR feedback: comment fixup and _privateVariable

0ffdefb

fix whitespace

c12e27a

nguerrera merged commit f878ddb into dotnet:master Mar 16, 2018

nguerrera deleted the cache-package-resolve branch March 16, 2018 01:10

This was referenced Mar 30, 2018

_ComputeLockFileReferences/RunResolvePackageDependencies should be faster when projects are up-to-date #1116

Closed

Reduce data sent to project system in design-time builds #2100

Open

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

Closed

		@@ -59,58 +53,7 @@ public DiagnosticsHelper(ILog log)

		_diagnosticMessages.Add(diagnostic);

		if (logToMSBuild)


		/// <summary>
		/// Indicate to MSBuild ResolveAssemblyReferences that

Speed up incremental package asset resolution #2020

Speed up incremental package asset resolution #2020

Conversation

nguerrera commented Mar 5, 2018 • edited Loading

Incremental build --no-restore /m:1

Incremental parallel build --no-restore

Clean parallel build --no-restore (cleaned and restored beforehand)

nguerrera commented Mar 5, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

davkean left a comment • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mikeharder commented Mar 6, 2018 • edited Loading

nguerrera commented Mar 6, 2018

mikeharder commented Mar 6, 2018

rainersigwald commented Mar 6, 2018

nguerrera commented Mar 8, 2018

dsplaisted left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nguerrera Mar 13, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nguerrera Mar 15, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nguerrera commented Mar 15, 2018

nguerrera commented Mar 16, 2018

nguerrera commented Mar 5, 2018 •

edited

Loading

nguerrera commented Mar 5, 2018 •

edited

Loading

davkean left a comment •

edited

Loading

mikeharder commented Mar 6, 2018 •

edited

Loading

nguerrera Mar 13, 2018 •

edited

Loading

nguerrera Mar 15, 2018 •

edited

Loading