dotnet / project-system

The .NET Project System for Visual Studio
MIT License
969 stars 387 forks source link

Give the developer tools to troubleshoot the Fast Up To Date heuristic misfires. #7948

Open MarkKharitonov opened 2 years ago

MarkKharitonov commented 2 years ago

Summary

The build inside Visual Studio IDE sometimes takes too much time, because projects are recompiled over and over again. However, developers do not know whether the projects are truly recompiled or it is the Fast Up To Date heuristic that fails to recognize that projects are up to date and submits them to msbuild every time. And we all know it takes eternity to msbuild to burn through all the targets necessary to determine that the project is up to date - that is the raison d'être for the heuristic in the first place.

There are 2 cases of heuristic misfires:

  1. The project is up-to-date, but the heuristic fails to recognize it and submits the project to msbuild anyway.
    • This one is possible to recognize if we build the project with diagnostics log level. This is because the first line is output by the heuristic and it often provides the reason why the build is necessary, like: 1>Project 'xyz' is not up to date. Input file 'abc' is modified after output file ''. OR 1>Project 'xyz' is not up to date. Project item 'abc' has 'Copy to Output Directory' attribute set to 'Copy always'.. This is extremely helpful.
  2. The project is NOT up-to-date, but the heuristic fails to recognize it and does NOT submit the project to msbuild.
    • There is no diagnostics for this case at all.
    • It has more potential for producing incorrect build results.

The current situation where the only output from the heuristic is during the diagnostic build is problematic. Indeed, we care about the heuristic only for big solutions, but building a big solution at the diagnostic log level is not feasible - it makes the output pane explode with gazillion lines of output when all we need is just the first line for every project being built.

It would be very useful to decouple the build output from the heuristic diagnostic messages. Like having a dedicated heuristic output pane or better still being able to configure it to write to a file, so that invoking devenv build from the command line could also produce the heuristic diagnostics.

An ideal solution would be to have a command line devenv flag to provide the heuristic log file path AND have the dedicated output pane.

Another part of the troubleshooting is being able to produce binary logs from the builds that get submitted to msbuild. It is very important, since it lets us confirm that the project is indeed up-to-date or not. Unfortunately, the super useful Project System Tools extension is effectively broken for VS 2022 - the binary log it produces lacks crucial information.

User Impact

In our organisation we have hundreds of developers working on a couple of big solutions. When projects are rebuilt without a seemingly good reason our time is wasted. And when there is no easy way to troubleshoot these rebuilds devs either give up or depend on someone who knows all these details and there are very few people with this level of such specific knowledge in our organisation. I assume our situation is typical.

MarkKharitonov commented 2 years ago

The Options|Projects and Solutions|SDK-Style Projects settings sheet seems very relevant for my question. Unfortunately, it only works for the SDK style projects. And the subject of this post are big solutions in enterprise applications which are likely to contain a lot of legacy projects.

drewnoakes commented 2 years ago

Hi @MarkKharitonov. Thanks for your thoughts here.

There are 2 cases of heuristic misfires

Both of these aren't great, but the underbuild is much worse (correctness) than overbuild (performance). The FUTD check is a heuristic and cannot be correct in all cases. When we believe it cannot be correct, we favour overbuild.

The current situation where the only output from the heuristic is during the diagnostic build is problematic

If you set the log level to "minimal" then you only see log output when a build is scheduled. If you set it to "Info" or "Verbose" then you'll see log output on every build.

As you say, increasing the log level for large solutions can be problematic due to the volume of output. This also hurts performance.

In practice, using "Minimal" level is a good default. When investigation is needed into a specific project's build, setting a higher log level and building only that project gives rich information, while also keeping the amount of log output manageable.

...so that invoking devenv build from the command line could also produce the heuristic diagnostics.

devenv /build does not use the fast up-to-date check. The fast up-to-date check only works because VS is a long-running process that has extracted information from the project ahead of time. In a command line build, that data is not available, so MSBuild is always invoked.

Unfortunately, the super useful Project System Tools extension is effectively broken for VS 2022 - the binary log it produces lacks crucial information

This is a known limitation of the tool, and is not new in VS2022. There are some issues tracking this, such as:

In cases where a full-fidelity binlog is needed, you can follow these steps to get them.

when there is no easy way to troubleshoot these rebuilds devs either give up or depend on someone who knows all these details and there are very few people with this level of such specific knowledge in our organisation

I can sympathise with this situation. We are trialling a feature that reports when a project's incremental build is broken. It runs the fast up-to-date check again after the build. If the project is not up-to-date, it's likely the project's incrementality is broken. This feature is enabled whenever the log level is higher than "None". If you keep the setting on "Minimal" (a good default) then you should see these messages when incremental build failures are detected.

Unfortunately, there is no one path to diagnosing these failures. There are common patterns that tend to trigger these issues, but each requires its own investigation on a case-by-case basis.

The Options|Projects and Solutions|SDK-Style Projects settings sheet seems very relevant for my question. Unfortunately, it only works for the SDK style projects. And the subject of this post are big solutions in enterprise applications which are likely to contain a lot of legacy projects.

Indeed everything I've written above relates to SDK-style projects. Legacy projects have their own fast up-to-date check that works differently, has fewer features, and has different logging.

We have some documentation on how to enable up-to-date check logging for non-SDK-style projects.

Give the developer tools to troubleshoot the Fast Up To Date heuristic misfires

Today those tools are up-to-date check logging, the Project System Tools extension, and the MSBuild Structured Log Viewer.

We are definitely receptive to ideas on how this could be improved.

I'm interested to know if the incremental build failure detection is helpful, for your SDK-style projects at least.

MarkKharitonov commented 2 years ago

Hi @drewnoakes. Thanks for the detailed response.

I would like to note that testing FUTD with the command line devenv does make sense when working with the legacy projects (and we have quite a lot of these yet). From observing how VS IDE works vs command line devenv I have arrived at the conclusion that FUTD for legacy projects does work for devenv, except we do not get the time saving benefits, because VS IDE accumulates the state (like you have mentioned) throughout its lifetime whereas devenv command line need to build it afresh every time. But I am pretty sure the FUTD is there. I have a tiny solution with two very small projects (one SDK style, another legacy) - https://github.com/MarkKharitonov/FUTDExperiments.git. Building it twice on the command line with devenv results in the following output:

C:\work\FUTDExperiments [master ≡]> dotnet restore
  Determining projects to restore...
  Restored C:\work\FUTDExperiments\SDKStyle\SDKStyle.csproj (in 70 ms).
C:\work\FUTDExperiments [master ≡]> devenv .\FUTDExperiments.sln /build

Microsoft Visual Studio 2022 Version 17.0.4.
Copyright (C) Microsoft Corp. All rights reserved.
Build started...
1>------ Build started: Project: Legacy, Configuration: Debug Any CPU ------
2>------ Build started: Project: SDKStyle, Configuration: Debug Any CPU ------
1>  Legacy -> C:\work\FUTDExperiments\Legacy\Bin\Debug\Legacy.dll
2>SDKStyle -> C:\work\FUTDExperiments\SDKStyle\bin\Debug\net5.0\SDKStyle.dll
========== Build: 2 succeeded, 0 failed, 0 up-to-date, 0 skipped ==========
C:\work\FUTDExperiments [master ≡]> devenv .\FUTDExperiments.sln /build

Microsoft Visual Studio 2022 Version 17.0.4.
Copyright (C) Microsoft Corp. All rights reserved.
Build started...
1>------ Build started: Project: SDKStyle, Configuration: Debug Any CPU ------
1>SDKStyle -> C:\work\FUTDExperiments\SDKStyle\bin\Debug\net5.0\SDKStyle.dll
========== Build: 1 succeeded, 0 failed, 1 up-to-date, 0 skipped ==========
C:\work\FUTDExperiments [master ≡]>

We can see that the Legacy project was not submitted to msbuild, which is also confirmed by the 1 up-to-date output.

So I think it is fair to say that testing legacy FUTD heuristic using devenv is a viable technique. And it is very much relevant for large enterprise applications with a sizable share of legacy projects.

What I fould lacking in the Project System Tools (and I am convinced it is a VS 2022 regression) is the reason why targets are rebuilt. In the past one could see a message about file X being older than file Y or something like that. At first I thought it is a problem of the msbuild log viewer and even opened a regression bug there (https://github.com/KirillOsenkov/MSBuildStructuredLog/issues/568). But it seems that Project System Tools does not collect this information anymore.

The instructions on how to collect binary logs from VS IDE and to enable the legacy FUTD output are super useful - thank you.

I do not remember seeing any messages about incremental build failures for SDK style projects. Maybe we do not have such problems? I have an example in mind where this could be an issue especially for SDK style projects. I actually reported on that in this thread - https://github.com/dotnet/msbuild/issues/6401. It has to do with build time tools that generate source code files. I will try to come up with a minimal reproduction to check out this incremental build failure detection.

MarkKharitonov commented 2 years ago

Reproducing the auto generated files issue is not easy. There are all kinds of warnings which push one to use the following pattern:

<Compile Remove="xyz.g.cs" />
<Compile Include="xyz.g.cs" />

Which makes sure the generated file is always inserted at the same place, which preserves the incremental nature of the build.