Incremental build failure message might not contain enough information

[drewnoakes]

@tmat provided a verbose FTUDC log that showed the following:

1>FastUpToDate: Project is up-to-date. (Microsoft.CommonLanguageServerProtocol.Framework) ... <snip output from projects 2, 3 and 4> ... WARNING: Potential build performance issue in 'Microsoft.CommonLanguageServerProtocol.Framework.csproj'. The project does not appear up-to-date after a successful build: The set of project items was changed more recently (2022-10-14 09:55:06.405) than the last successful build start time (2022-10-14 09:55:06.363), not up-to-date. See https://aka.ms/incremental-build-failure.

Or in other words:

1. The project is checked and deemed up-to-date.
2. The validation phase decides the project is not up-to-date and logs the warning.

Generally we've found that warnings about item changes can be debugged by looking at the earlier log messages, which list what items were added and/or removed. In this case there were no changes in that output.

Some questions come to mind:

1. Why was the validation running here, given the project was up-to-date?
2. Could the build of projects 2, 3 or 4 have changed the items in project 1 by the time the validation came around? If so, maybe all validation should run at the end of the solution build to better catch these kinds of issues.
3. Can we expose more information about the validation failure? If verbose logging is enabled, perhaps we retain all log messages to be displayed only if validation fails.

[drewnoakes]

@tmat in your scenario, does the next build of the project appear up-to-date? Given the validation believes the project is not up-to-date, I would expect the next build to include details of added/removed items.

[tmat]

@drewnoakes I don't remember if it did. It only happens occasionally.

[tmat]

Happened again.

First build:

Build started...
WARNING: Potential build performance issue in 'Microsoft.CodeAnalysis.csproj'. The project does not appear up-to-date after a successful build: The set of project items was changed more recently (10/18/2022 3:24:51 PM) than the last successful build start time (10/18/2022 3:24:51 PM), not up-to-date. See https://aka.ms/incremental-build-failure.
1>------ Build started: Project: Microsoft.CodeAnalysis.Workspaces, Configuration: Debug Any CPU ------
1>D:\R5\src\Workspaces\Core\Portable\Workspace\Solution\AnalyzerConfigDocumentState.cs(34,35,34,51): error CS0100: The parameter name 'solutionServices' is a duplicate
1>Done building project "Microsoft.CodeAnalysis.Workspaces.csproj" -- FAILED.
1>D:\R5\src\Workspaces\Core\Portable\Workspace\Solution\AnalyzerConfigDocumentState.cs(34,35,34,51): error CS0100: The parameter name 'solutionServices' is a duplicate
1>Done building project "Microsoft.CodeAnalysis.Workspaces.csproj" -- FAILED.
========== Build: 0 succeeded, 1 failed, 1 up-to-date, 0 skipped ==========
========== Elapsed 00:02.569 ==========

Second build (verbose logging):

Build started...
1>FastUpToDate: Checking configuration Debug|AnyCPU|netcoreapp3.1: (Microsoft.CodeAnalysis)
1>FastUpToDate: The set of project items was changed more recently (2022-10-18 08:24:51.046) than the last successful build start time (2022-10-18 08:24:51.008), not up-to-date. (Microsoft.CodeAnalysis)
1>FastUpToDate:     The set of changed items is empty. (Microsoft.CodeAnalysis)
1>FastUpToDate: Up-to-date check completed in 0.4 ms (Microsoft.CodeAnalysis)
1>------ Build started: Project: Microsoft.CodeAnalysis, Configuration: Debug Any CPU ------
1>Microsoft.CodeAnalysis -> D:\R5\artifacts\bin\Microsoft.CodeAnalysis\Debug\netcoreapp3.1\Microsoft.CodeAnalysis.dll
1>Microsoft.CodeAnalysis -> D:\R5\artifacts\bin\Microsoft.CodeAnalysis\Debug\netstandard2.0\Microsoft.CodeAnalysis.dll
2>FastUpToDate: Checking configuration Debug|AnyCPU|netcoreapp3.1: (Microsoft.CodeAnalysis.Workspaces)
2>FastUpToDate: The set of project items was changed more recently (2022-10-18 08:24:51.386) than the last successful build start time (2022-10-14 10:20:49.856), not up-to-date. (Microsoft.CodeAnalysis.Workspaces)
2>FastUpToDate:     The set of changed items is empty. (Microsoft.CodeAnalysis.Workspaces)
2>FastUpToDate: Up-to-date check completed in 0.2 ms (Microsoft.CodeAnalysis.Workspaces)
2>------ Build started: Project: Microsoft.CodeAnalysis.Workspaces, Configuration: Debug Any CPU ------
2>D:\R5\src\Workspaces\Core\Portable\Workspace\Solution\AnalyzerConfigDocumentState.cs(34,35,34,51): error CS0100: The parameter name 'solutionServices' is a duplicate
2>Done building project "Microsoft.CodeAnalysis.Workspaces.csproj" -- FAILED.
2>D:\R5\src\Workspaces\Core\Portable\Workspace\Solution\AnalyzerConfigDocumentState.cs(34,35,34,51): error CS0100: The parameter name 'solutionServices' is a duplicate
2>Done building project "Microsoft.CodeAnalysis.Workspaces.csproj" -- FAILED.
========== Build: 1 succeeded, 1 failed, 0 up-to-date, 0 skipped ==========
========== Elapsed 00:03.214 ==========

[tmat]

Then 3rd and 4th builds, building the entire solution: 3rd.log 4th.log

[Naveen61097]

Any updates on this?

[drewnoakes]

@Naveen61097 do you have a reliable repro for this that you could share?

[sisomvanshi]

We seem to be running into similar issues with incremental builds using latest VS 17.6.2 on one of our larger projects. Is there a proposed solution for this?

In our case, certain low-level projects in our solution will report something like below even during null builds (at verbose logging level), causing a whole lot of dependent projects to rebuild.

545>FastUpToDate: The set of project items was changed more recently (2023-06-13 11:38:33.274) than the last successful build start time (2023-06-13 11:34:53.340), not up-to-date. (XYZ) 545>FastUpToDate: The set of changed items is empty. (XYZ) 545>FastUpToDate: Up-to-date check completed in 0.6 ms (XYZ) 545>------ Build started: Project: XYZ, Configuration: Release x64 ------

Without more details in the log it's hard to determine what exactly is getting updated and even create a repro case. Ideally we'd want this not to happen at all to prevent unnecessary rebuilds.

[drewnoakes]

@sisomvanshi this can happen when an item is added then removed, or vice versa. You may be able to diagnose the situation with that information. If you have a repro you can share, it'd be helpful.

We may be able to fix this in VS directly. It'll require some investigation and reworking of the code. We are tracking that in #8933.

[sisomvanshi]

@drewnoakes sounds good, would be great to get that handled by VS. This is imapcting our incremental build times a lot.

In the interim, having the name of the item listed in the log would also be helpful.