microsoft / MSBuildSdks

MSBuild project SDKs
MIT License
449 stars 80 forks source link

CopyOnWrite causes MSBuild to always copy (or at least alter the modification timestamp of) the output file of a project #528

Closed alexrp closed 7 months ago

alexrp commented 7 months ago

I have a solution where library project Foo depends on executable project Bar at build time. That is, Bar needs to be built before Foo so that the build process of Foo can run Bar and embed the file it produces.

The setup looks a bit like this (Foo.csproj):

<ItemGroup>
  <ProjectReference Include="../bar/bar.csproj"
                    Private="false"
                    ReferenceOutputAssembly="false"
                    OutputItemType="Bar" />
</ItemGroup>

<Target Name="_RunBar"
        Inputs="@(Bar); @(_BarInputs)"
        Outputs="$(_BarOutputPath)"
        BeforeTargets="BeforeResGen">
  <Exec Command="dotnet @(Bar) @(_BarInputs) $(_BarOutputPath) ... args ..."
        StandardOutputImportance="low"
        StandardErrorImportance="low" />

  <ItemGroup>
    <EmbeddedResource Include="$(_BarOutputPath)"
                      Type="Non-Resx"
                      WithCulture="false" />
  </ItemGroup>
</Target>

(I'm simplifying a lot here, but this is the gist of it. I can give a link to the repository with build instructions, but be warned that it requires ~14 GB to clone and build.)

This target has worked fine until now; the problem occurs when adding the Microsoft.Build.CopyOnWrite package reference. Now, _RunBar is executed on every build because MSBuild always thinks that @(Bar) (i.e. the output executable from the Bar project) is newer than the output file $(_BarOutputPath). I verified this with a binlog.

The @(_BarInputs) files are not touched by the build at all and are mostly static, and removing @(Bar) from Inputs makes the target not run on every build, though of course it no longer has the intended effect of rerunning the target when the executable is rebuilt.

And indeed, looking at the timestamps of the files, the thing that stands out is that Bar.dll seems to be copied to the Bar project's output directory even when it hasn't actually changed, resulting in its modification time changing on every build. This is different from 'base' MSBuild which does not do this. I don't know why this is happening, but it certainly seems to be where things are going wrong in all this.

This is on Windows 10.0.23612.1000, .NET SDK 8.0.101, Microsoft.Build.CopyOnWrite 1.0.300. The build is happening on a ReFS Dev Drive.

erikmav commented 7 months ago

Thanks for reporting, will examine with a unit test suite ETA next work week.

alexrp commented 7 months ago

Simple test case:

$ dotnet new console
$ dotnet build
$ ls -lah bin/Debug/net8.0/test.dll
-rwxr-xr-x 1 Alex Rønne Petersen Alex Rønne Petersen 4.5K Jan 12 23:26 bin/Debug/net8.0/test.dll
$ sleep 120
$ dotnet build
$ ls -lah bin/Debug/net8.0/test.dll
-rwxr-xr-x 1 Alex Rønne Petersen Alex Rønne Petersen 4.5K Jan 12 23:26 bin/Debug/net8.0/test.dll
$ dotnet add package Microsoft.Build.CopyOnWrite
$ dotnet build
$ ls -lah bin/Debug/net8.0/test.dll
-rwxr-xr-x 1 Alex Rønne Petersen Alex Rønne Petersen 4.5K Jan 12 23:29 bin/Debug/net8.0/test.dll
$ sleep 120
$ dotnet build
$ ls -lah bin/Debug/net8.0/test.dll
-rwxr-xr-x 1 Alex Rønne Petersen Alex Rønne Petersen 4.5K Jan 12 23:31 bin/Debug/net8.0/test.dll
erikmav commented 7 months ago

Reproduced locally, thanks for the easy test case. Tracking down the breakdown in up-to-date check or copy paths.

erikmav commented 7 months ago

Verified it happens on NTFS as well, so it's not related to CoW linking.

alexrp commented 7 months ago

FWIW, I just tried Microsoft.Build.CopyOnWrite in a few more of my repos. Those are all just fairly normal C# projects (w/ Traversal), no fancy custom targets like this case. In all of these, a build where everything was up to date increased in time by 20-25%. I haven't looked deeper into it than that, but I would assume it comes back to this same issue. :thinking:

alexrp commented 7 months ago

In all of these, a build where everything was up to date increased in time by 20-25%. I haven't looked deeper into it than that, but I would assume it comes back to this same issue. 🤔

I dug a bit further and the slowdown is actually at the dotnet publish step (self-contained w/ a RID). That kind of makes sense if the issue is that files are just being copied unconditionally, since publishing copies a whole boatload of assemblies and native binaries.

erikmav commented 7 months ago

Found one issue where CoW linking was not setting LastWriteTimeUtc to the timestamp of the source file which will account for the Dev Drive out-of-date check problems. Still examining the NTFS case where that code should have been the same as the original MSBuild Copy code.

erikmav commented 7 months ago

This is mysterious: I reran the dotnet new console test case you provided above on both NTFS and Dev Drive today and it does not reproduce - it looks like MSBuild decides that the output files are up to date and does not rebuild. This is very puzzling as I had Dev Drive and NTFS repros last week. I've now tried with two new projects in two different subdirectories in each filesystem type. No reboot in between or OS or MSBuild updates that I'm aware of.

alexrp commented 7 months ago

Hm. It still reproduces on my end with 1.0.300 FWIW. I've done quite a few reboots over the last few days, and one OS update (insider build).

🤔

czdietrich commented 7 months ago

Just wanted to mention we are also affected by this problem when Microsoft.Build.CopyOnWrite is added that the up-to-date check fails, since the linked DLLs in the bin folder will have a newer time stamp than the original from the obj folder. Also reproducible with 1.0.300.

erikmav commented 7 months ago

.302 released with the fix: https://github.com/microsoft/MSBuildSdks/releases/tag/Microsoft.Build.CopyOnWrite.1.0.302

czdietrich commented 7 months ago

This update seems to fix the issue for us. Thank you, nice work. 🎉

alexrp commented 7 months ago

Can confirm it now works as expected on my end as well. Thank you!