Repository navigation
Update .nupkg.metadata LastAccessedTime on restore - #4222
Conversation
ghost
added
the 
|
Are you sure that the file timestamps are actually getting updated? When I investigated myself early December last year (just before some emergenies came up, so I was unable to continue the work), I found that your branch from that time was not being used in several scenarios, such as no-op restores. I can't remember if restores that needed to update the assets file, but did not need to download anything, updated the timestamp. So, a possible reason that there's no measured perf impact may be that your code isn't actually running in the scenario you copied the results from. Also, this change should really have a test, because it's too easy for this to regress with future changes. A new test in |
| // for the life of this restore. | ||
| // Locking is done at a higher level around the id | ||
| _packageCache.TryAdd(path, package); | ||
| if(_packageCache.TryAdd(path, package)) |
There was a problem hiding this comment.
If we're to accept this, I think we should consider an opt-in @zivkan.
There was a problem hiding this comment.
Understood, I'll see how to implement that shortly.
|
|
||
| var result = await command.ExecuteAsync(); | ||
|
|
||
| Assert.True(firstTouchTime < File.GetLastWriteTimeUtc(packageMetadata)); |
There was a problem hiding this comment.
@mfkl
Thank you for your contribution. Maybe to simulate real life scenario better to add delay (await Task.Delay(1000);). Currently unit test is failing here, most likely due to NoOp operation or C# code is running too fast, please check.
In case of noop, it was not indeed. Seems to be OK now, I'll run the perf script against the new build and get back to you soon with the results.
That's in addition to the existing test in this PR ( |
| /// <summary> | ||
| /// No metadata file found | ||
| /// </summary> | ||
| NU5502 = 5502, |
There was a problem hiding this comment.
I don't think this is the appropriate log code.
Please refer to the top of the file for guidance on log codes.
There was a problem hiding this comment.
I did, went for NU1110 but honestly not sure this is OK for this feature.
| { | ||
| foreach (var packageFilePath in cacheFile.ExpectedPackageFilePaths) | ||
| { | ||
| var nupkgMetadataPath = Path.Combine(Path.GetDirectoryName(packageFilePath), ".nupkg.metadata"); |
There was a problem hiding this comment.
Wouldn't this end up touching fallback folders as well?
There was a problem hiding this comment.
A second unit test (or maybe modifying the new one in this PR) that validates that fallback folder .nupkg.metadata files can ensure this doesn't happen.
The test setup will be even more involved, but fallback folders use the same folder structure as the global packages folder, they're just supposed to be read-only. So, my best guess is that the test can restore a package into the global pacakges folder, move it to a fallback folder (create one if needed), modify the test's nuget.config to add this as a fallback folder, set the .nupkg.metadata file to an old timestamp, restore a second time, and ensure the file's timestamp has not changed.
There was a problem hiding this comment.
Wouldn't this end up touching fallback folders as well?
Should be fixed now.
zivkan
left a comment
zivkan
left a comment
There was a problem hiding this comment.
Getting perf measurements is more important than creating the string resource, since it'll determine whether or not this PR will be mergable. But creating the string resource isn't a lot of work, especially since we have plenty of examples of it in our code. Look anywhere else RestoreLgMessage.CreateError or CreateWarning is used.
| } | ||
| catch (Exception ex) | ||
| { | ||
| RestoreLogMessage.CreateError(NuGetLogCode.NU1110, $"Touching the metadata file {nupkgMetadataPath} failed with {ex.Message}"); |
There was a problem hiding this comment.
User facing messages must come from string resources, so they can be localized into multiple languages.
There was a problem hiding this comment.
Also, something like Updating last access time on file {0} failed with {1} is more understandable, and less creepy, than "touching" for people who don't have knowledge of the unix touch command.
There was a problem hiding this comment.
Indeed, you're right. Will make that change.
Here is a few runs results Results
See https://github.com/mfkl/nuget-perf for details |
|
So reading the results for orleans, it's a 250ms hit, for a 3.3% change right? cc @aortiz-msft |
|
|
||
| restoreTime.Stop(); | ||
|
|
||
| await UpdateLastAccessTime(cacheFile); |
There was a problem hiding this comment.
This probably needs to be above the restoreTime.Stop() call.
| telemetry.TelemetryEvent[TotalUniquePackagesCount] = cacheFile.ExpectedPackageFilePaths?.Count ?? -1; | ||
| telemetry.TelemetryEvent[NewPackagesInstalledCount] = 0; | ||
|
|
||
| await UpdateLastAccessTime(cacheFile); |
There was a problem hiding this comment.
Same here, probably best if included in the measured restore time.
| } | ||
| } | ||
|
|
||
| private async Task UpdateLastAccessTime(CacheFile cacheFile) |
There was a problem hiding this comment.
One way of reducing the perf hit here would be to update is once per operation, rather than once per project.
Packages are commonly shared among projects, so it might lead to some good savings.
I think it could be something that you test on the side and post the perf results for comparison.
There was a problem hiding this comment.
One way of reducing the perf hit here would be to update is once per operation, rather than once per project.
Sorry, but I don't understand what you mean. Could you clarify what you mean by 'operation' please?
There was a problem hiding this comment.
Sure.
Restore always need to run on a per project level.
Even when projects have project references to each other, the restores there can happen independently.
When you run restore on the commandline, or in VS, multiple restore for different projects are kicked off concurrently.
While the graph generation is fairly independent, things such as making http calls to the sources, package installation, package enumeration etc, are usually cached.
So if you have 2 projects, that both need Newtonsoft.Json, the same http calls will be reused, the package installation will happen only once etc.
Given that most of the time, the global packages folder across projects is shared, you could do the timestamp update only once.
For example, Newtonsoft.Json is a package that's a part of ~75% of NuGet's projects. There's really no benefit to updating the timestamp 75 times.
You consider testing the perf hit if you try to ensure these updates happen only once.
An easy and recent example is the LockFileBuilderCache.
There was a problem hiding this comment.
So if I understand correctly, what you are saying is that in the case of .sln restore input only (not individual project restores), the timestamp reset should happen only once for any given package/version that is referenced by multiple projects of the solution.
I'm looking at making these changes in RestoreRunner.cs, but it is not obvious to me how to properly unit test this and how to make it play nice code-wise with the individual project restore code path.
There was a problem hiding this comment.
So if I understand correctly, what you are saying is that in the case of .sln restore input only (not individual project restores), the timestamp reset should happen only once for any given package/version that is referenced by multiple projects of the solution.
Yes that's the idea.
I'm looking at making these changes in RestoreRunner.cs, but it is not obvious to me how to properly unit test this and how to make it play nice code-wise with the individual project restore code path.
That'd be trickier to test for sure.
I don't have a good suggestion, because it's really be at best once, rather at most once, you'd want to avoid any lock contention there.
Did you check if it makes a difference perf wise?
There was a problem hiding this comment.
Did you check if it makes a difference perf wise?
I don't see much difference when using the dotnet/orleans as a test solution, but with a large solution with many projects sharing similar package references, it should definitely be faster.
I don't know how common those solution patterns are though. I can try to build one though.
This is my change regarding this optimization mfkl@523387b
erdembayar
added
Community
644f0d7 to
ac19341
Compare
|
Rebased on current |
|
Thanks, @erdembayar, for adding the CI label. @nkolev92, @zivkan, any chance we could get some eyes on this sucker? Would be good to get some feedback for @mfkl if there's something else to be done here. |
|
I will be, I assigned myself the linked issue, but I guess I should have been clearer and assigned the PR to myself as well. However, I'm going on vacation soon, so I won't be able to dedicate enough time to this until late December. NuGet is the first open-source product I've ever worked on, and I'm learning how much overhead/unscheduled work it causes when we get external contributions. Since we get such infrequent contributions, we can't even schedule time just to review/test contributions each month, since there's usually nothing to do. However, that doesn't excuse the slow responses we've had so far. I'm sorry we haven't been more proactive in getting this done. Particularly as someone in the team who wants this feature, I should have done more. Anyway, as previous comments point out, we had concerns about perf impact. I see the feature is now behind a configuration flag. I need to verify it's off by default, but if the perf impact is non-trivial, then this should be satisfactory to the people who care most about performance. I want to verify performance myself. I know @mfkl shared their measurements, but we've had other cases where the contributor's measurements directly, and significantly, contradict my own measurements. Since updating timestamps doesn't sound like a whole lot of work, I hope my own perf testing on physical machine vs cloud vm doesn't show anything interesting, which willl give me confidence to merge it. But I need to check, which needs some time. |
| return restoreSummaries; | ||
| } | ||
|
|
||
| private static async Task TouchMetadata(IEnumerable<RestoreSummaryRequest> restoreRequests, ILogger log) |
There was a problem hiding this comment.
| private static async Task TouchMetadata(IEnumerable<RestoreSummaryRequest> restoreRequests, ILogger log) | |
| private static async Task UpdateLastAccessTime(IEnumerable<RestoreSummaryRequest> restoreRequests, ILogger log) |
| /// <summary> | ||
| /// Whether the cache expiration feature is enabled for the global package folder | ||
| /// </summary> | ||
| public bool CacheExpirationEnabled { get; } |
There was a problem hiding this comment.
The name "client policy" isn't very obvious, but this is used for signed package validation. So, configuration related to the global packages folder is not appropriate here. This class being in the project/assembly NuGet.Packaging is another hint. I think the RestoreRequest in NuGet.Commands is a good place to put it, especially since it's where the path to the (global) packages folder appears to be.
Also, we (NuGet team) don't refer to the global packages folder as a cache (even if customers constantly do), so we need a different name. I really can't imagine we'll ever auto-delete unused packages on restore, so I suggest a setting name something like ForceUpdatePackageLastAccessTime.
|
|
||
| public static readonly string Package = "package"; | ||
|
|
||
| public static readonly string CacheExpiration = "cacheExpiration"; |
There was a problem hiding this comment.
Like I mentioned in another comment, I think this should be called something like forceUpdatePackageLastAccessTime. I don't like that it's so long, so feel free to come up with a better idea, but I think we should separate updating the file timestamp vs deleting packages. I can't imagine we'll ever auto-delete unused packages. The perf impact will be too high, even if we only check once per [insert your preferred time period]. I think it will probably always be a manual and explicit action customers will need to take.
| private static async Task TouchMetadata(IEnumerable<RestoreSummaryRequest> restoreRequests, ILogger log) | ||
| { | ||
| var uniquePackageList = restoreRequests.SelectMany(restoreRequest => restoreRequest.Request.Project.TargetFrameworks.SelectMany(tfm => tfm.Dependencies)).Distinct(); | ||
| var repoRoot = restoreRequests.First().Request.DependencyProviders.GlobalPackages.RepositoryRoot; |
There was a problem hiding this comment.
What value does restoreRequests.First().PackagesDirectory contain?
| } | ||
| catch (Exception ex) | ||
| { | ||
| await log.LogAsync(RestoreLogMessage.CreateError(NuGetLogCode.NU1110, |
There was a problem hiding this comment.
If a package is used from a fallback folder, hence the package doesn't exist in the global packages folder, isn't this going to throw, and therefore spam the logs? In the case of a package used from fallback folder instead of the global packages folder, not only is the error non-actionable by the customer, it's by-design and therefore not a problem at all.
Even when there's an error updating the timestamp, for example virus scanner has the file open (Windows errors out when trying to update the LastWriteTime when the file is open, I'm not sure about LastAccessTime), I don't know if we'd want to fail restore and block builds (fail CI if anyone has this configured on their CI agent). I think a warning would be sufficient. What do you think?
| return SignatureValidationMode.Accept; | ||
| } | ||
|
|
||
| public static bool GetCacheExpirationStatus(ISettings settings) |
There was a problem hiding this comment.
I expect that all the other configuration settings have unit tests, and while you've added tests for updating the file timestamp, we should also add unit tests for configuration in tests/NuGet.Core.Tests/NuGet.Configuration.Tests.
| /// InvalidUndottedFrameworkWarning | ||
| /// </summary> | ||
| NU5501 = 5501, | ||
| NU5501 = 5501 |
There was a problem hiding this comment.
let's not remove the last comma, so that if NU5502 or higher gets added, it doesn't need to modify this line
|
Thanks, @zivkan!
No worries at all. I can only imagine the volume of incoming input you receive on some of these projects. Along those lines, I know that issues can get easily lost in the shuffle so I try to poke them along every once in a while. We're really just here to try and help, not burden you with even more work.
Yep, all understood. Thanks for taking your time on it and making sure we get it right. |
zivkan
left a comment
zivkan
left a comment
There was a problem hiding this comment.
I really like the idea of a nuget.config setting to enable/disable this feature. However, as commented, the current commit doesn't work at all. I only budgeted time to review this PR, not fix it. If I end up finishing my other planned work, I'll try making some changes and see if I have permission to push changes. But for now, I'm moving on to other work.
|
|
||
| private static async Task TouchMetadata(IEnumerable<RestoreSummaryRequest> restoreRequests, ILogger log) | ||
| { | ||
| var uniquePackageList = restoreRequests.SelectMany(restoreRequest => restoreRequest.Request.Project.TargetFrameworks.SelectMany(tfm => tfm.Dependencies)).Distinct(); |
There was a problem hiding this comment.
This gets only the PackageReferences from the projects, but none of the transitive packages. I don't see any (efficient) way to get the list of actual packages from within RestoreRunner.RunAsync, at least, not the part outside the per-project fan-out. While it's a nice way (with the .Distinct()) to ensure that each package is only updated once, it's going to miss a lot of packages.
If you have a look at LocalPackageFileCache.cs, you see how we implemented a shared cache for a single restore operation and avoid hitting the disk multiple times* per package. The same approach (in fact, I think it's entirely appropriate to use the same class) for updating package timestamps.
- mostly. ConcurrentDictionary doesn't promise that
GetOrAddwill call the factory method exactly once, it only promises that only one value will be used.
|
|
||
| foreach (var package in uniquePackageList) | ||
| { | ||
| var packageMetadataFile = Path.Combine(repoRoot, package.Name, package.LibraryRange.VersionRange.OriginalString, ".nupkg.metadata"); |
There was a problem hiding this comment.
There's two major problems here:
package.Nameuses the case specified in thePackageReference, and on filesystems that are case sensitive, this is fail if the case specified in the msbuild file does not match the path it was extracted toLibraryRange.VersionRange.originalStringwon't work in a whole bunch of scenarios. Firstly, when I debugged this it was returning values like[13.0.1, ), meaning there wasn't a single successful file timestamp update. Secondly, it won't work for anyone using floating versions (*, or6.*, or if it does work, it'll restore the wrong version). Similarly, any restore that ends up with NU1603 will not work.
We have code somewhere that does path normalization to avoid these problems. I thought it was in PackagePathResolver.cs, but I don't see any ToLowerInvariant in there, so I guess it's somewhere else. Given that this commit clearly hasn't been tested (I'm also time limited with the number of things I need to work on. I appriciate community members spending time to help us with pull requests but pull requests that don't work or clearly introduce bugs is a waste of our time reviewing), I'm not going to hunt down the exact helper method to reuse now, but I'd start with debugging PackageExtractor.cs and see how the path it uses gets generated.
|
Thanks for your review. I'll work on a new version to take into account all of your remarks and submit it to this PR. I did test things as best I could, but apparently not properly/enough. Hopefully the time you've already invested in this review means the next version will be quick for you to review. |
|
Team Review: Per our CONTRIBUTING doc, we're waiting for a response to comments. Please respond. |
|
I will push a new version to this PR this week. |
afd1eee to
ad3ff47
Compare
zivkan
changed the title
|
Team Triage: The current plan is to merge this PR by end of day today unless there is any other actionable feedback. |
erdembayar
left a comment
erdembayar
left a comment
There was a problem hiding this comment.
Great contribution.
Just 1 comment, it's not blocking.
…ache.cs Co-authored-by: Erick Yondon <[email protected]>
|
Thank you all for the reviews! |
7 participants
Bug
Fixes: First part of the work toward NuGet/Home#4980
Regression? No.
Description
test\NuGet.Core.FuncTests\Dotnet.Integration.TestsThis is a short diff that updates the last write time of metadata files of nuget packages on restore operations. The first step toward implementing a cache clean-up and expiration policy, the actual deletion should come in a follow up PR.
The main focus point should be performance, namely that it does not impact (too much, ideally at all) no-op restore operations performance.
dev-b58613fbc338b8e142d29b3bdb74e92a83a259fb
my branch (caching-touch-metadata2)
I did not find any meaningful differences with the no-op performance tests I've done using GitHub Actions. If you have any feedback regarding those, please let me know.
You can find my perf test investigations here https://github.com/mfkl/nuget-perf/blob/master/.github/workflows/ci.yml
Note: there is currently no exception handling if
SetLastWriteTimeUtcthrows.PR Checklist
PR has a meaningful title
PR has a linked issue.
Described changes
Tests
Documentation