VS19 Package Restore repeats 14 times

[RobSwDev]

Our Visual Studio solution (146 projects) often repeatedly restores nuget packages. This, combined with an issue with the Fast Up To Date check, means that our builds are much slower than necessary.

Any ideas why this should happen? Are there additional diagnostics I can turn on (for the fast up to date check, I had to fiddle with the VS private registry hives)

Restoring NuGet packages...
....
60 of 146 projects are up-to-date for restore.
Time Elapsed: 00:00:10.4271022
========== Finished ==========

Restoring NuGet packages...
....
65 of 146 projects are up-to-date for restore.
NuGet package restore finished.
Time Elapsed: 00:00:14.1169620
========== Finished ==========

Restoring NuGet packages...
....
3 of 146 projects are up-to-date for restore.
Time Elapsed: 00:00:15.0899035
========== Finished ==========

Using Visual Studio Version 16.6.2.
I attached sanitized package manager log. Restore was repeated 14 times in total (got bored trimming the log at around half that)

RepeatedNugetRestore.txt

[anangaur]

For SDK style projects, as you make changes to files that may impact the package graph, restores are triggered automatically. A couple of other questions related to this experience:

1. Does the restore prevent you from any other operation you want to do on Visual Studio?
2. Were these restores unnecessary? i.e. you didn't make any changes to the code or made code changes that shouldn't impact the package graph but the restores were triggered?
3. Is it the output message size that bothers you?

[RobSwDev]

To clarify - I wasn't working with Visual Studio - I was just waiting for it to "settle down". All but the first restore was unnecessary.

They don't explicitly prevent anything - the problem is that unnecessary package restores cause incremental builds to take much longer. Every project fails Visual Studio's Fast Up To Date check since various files in their obj directory get "touched".
Thus msbuild is called for each project (msbuild is then smart enough to realise that it doesn't need to call the compiler).
If I edit code inside a "leaf" project (by which I mean a project X such that no other project references X. A unit test project is almost always a "leaf") and rebuild, I expect the "up to date" check to say that all but project X are up to date.
In reality, it says that all projects are out-of-date due to the nuget restore.

When "Fast Up To Date" works, building X takes less than a second. When it fails, it's more like 30-40 seconds. So it's a useability/performance issue for me.

[RobSwDev]

Also, please see this comment: If package restore runs, and discovers that nothing needs updating, would it be possible for it to not change the timestamp on the various json files it creates? The file contents are not changing, only the timestamps. Which makes VS fail "Fast Up To Date".

[nkolev92]

Whenever the project system detects something is not up to date and it affects NuGet, it nominates.
Then NuGet responds with a restore, which should hopefully make everything up to date.

NuGet does have checks to identify whether the assets file is up top date before writing. We try not to write unless absolutely necessary.

Are you seeing the timestamp of the assets file get updated?
Is your repro similar to the one from the linked issue?

Can you provide a repro yourself?

Thanks.

[RobSwDev]

I will try to reproduce. I've observed that it is worse first thing in the morning (when I open the solution).

You say "when the project system detects something is not up to date" - is it possible for me to enable diagnostics so that I can find out what is considered not up to date?

What things would trigger nuget? Obviously any package or project reference changes in and *proj file. Also, if nuget updates project X, then it probably needs to update any project depending on X. However, I want to capture the cause of the "first" nuget trigger, as we don't update package/project references every day.

[zivkan]

Set the environment variable PROJECTSYSTEM_PROJECTOUTPUTPANEENABLED to 1, then launch Visual Studio. "Project" will be available in the "Output" window.

If the multiple NuGet restores correspond to multiple "BEGIN Nominate Restore" logs in the project output, then NuGet is correctly responding to the requests that project system is sending.

plug by @nkolev92 See link

[RobSwDev]

Ok - I see lots of new "BEGIN Nominate" messages, despite the fact that the solution has previously been completely restored, and nothing has changed since. So if the requests are spurious, that's an issue in the project system?

[nkolev92]

Yeah, that sounds like best handled on the project system side.

[nkolev92]

@RobSwDev

If you can look at all the BEGIN Nominate messages and find all the nominations for one project, can you spot any differences?

[RobSwDev]

I have noticed something further. We use floating versions for one of our package references.
The last time the restore loop occurred, I saw this in the project log:

Removing reference 'C:\Users\me\.nuget\packages\XXX\3.0.4.206\lib\net461\XXX.dll'
Adding reference 'C:\Users\me\.nuget\packages\XXX\3.0.4.207\lib\net461\XXX.dll'

These messages occurred more than 40 times (I cleared the log part way through so don't know how many more).
But this reference only exists in 17 projects. Could floating references be somehow causing the seeming package restore "loop"?

The "Begin Nominate Restore" messages seem ok, in that I don't see more than 1 per csproj.

[nkolev92]

The floating references by themselves would normally not affect the up to date check, #5445.

The "Begin Nominate Restore" messages seem ok, in that I don't see more than 1 per csproj.

That's a bit weird.
Do those nomination contain timestamps at all?

In that case the potential answer could be that the project loading is spaced out, and if they take too much time in between it can trigger many restores.

To help us better understand your exact scenario, it'd be great if you could start with a new instance of Visual Studio and file feedback using https://docs.microsoft.com/en-us/visualstudio/ide/how-to-report-a-problem-with-visual-studio?view=vs-2019#:~:text=In%20Visual%20Studio%2C%20select%20the,Send%20Feedback%20%3E%20Report%20a%20Problem..

That will contain some additional metrics that I can take a look at to better understand what's happening in your scenarios.

It's important that the feedback is submitted from the same VS instance that's having the problem.

[nkolev92]

@RobSwDev

Did you get a chance to file an issue through Visual Studio report a feedback?

[nkolev92]

Hey all,

I appreciate the time taking to file this issue.
Performance of restore in Visual Studio (and especially unnecessary restores) has been a recent focus of ours and we've done 3-4 large changes in this space that we hope will improve this behavior.

We still have lots of room for improvements, but given that we don't have a clear repro here, I'm going to close this issue.

I'd be happy to look into any additional logs to help triage and reopen/open new issues as necessary.