search

KirillOsenkov / MSBuildStructuredLog

A logger for MSBuild that records a structured representation of executed targets, tasks, property and item values.
MIT License
1.44k stars 190 forks source link

The timeline reported for building the generated .csproj.metaproj files does not make sense #543

Closed MarkKharitonov closed 2 years ago

MarkKharitonov commented 2 years ago

I have a build that was run with maxCpuCount = 4. Here is the command line as reported in the binary log:

"C:\Program Files (x86)\Microsoft Visual Studio\2019\BuildTools\MSBuild\Current\Bin\msbuild.exe"  "d:\_wf\01\4\s\xyz\Main.sln" 
/nologo 
/nr:false 
/dl:CentralLogger,"D:\_wf\01\_tasks\MSBuild_c6c4c611-aa2e-4a33-b606-5eaba2196824\1.179.0\ps_modules\MSBuildHelpers\Microsoft.TeamFoundation.DistributedTask.MSBuild.Logger.dll";"RootDetailId=3c007b75-eaef-4511-97bb-dcf915736ed1|SolutionDir=d:\_wf\01\4\s\xyz"*ForwardingLogger,"D:\_wf\01\_tasks\MSBuild_c6c4c611-aa2e-4a33-b606-5eaba2196824\1.179.0\ps_modules\MSBuildHelpers\Microsoft.TeamFoundation.DistributedTask.MSBuild.Logger.dll" -bl:c:\temp\binlogs\4\62.0.0.32712-0515-834-4.build.Main.binlog 
/v:m 
/m:4 
/p:OutDir=d:\_wf\01\4\b 
/p:AlternativeDataSource="server=torrdperfdb05;database=xyz-PR-AzureTest_AZG5DFC1BLD03_01" 
/restore 
/p:RestoreForce=true  
/err 
/nowarn:MSB3026,MSB3277,MSB3247,MSB3305 
/p:GatedCheckIn=true 
/p:platform="Any CPU" 
/p:configuration="Debug" 
/p:_MSDeployUserAgent="TFS_1a33a8ed-f8fd-4c08-9f44-440ea9f20315_build_8294_0"

The binlog's reporting of .csproj.metaproj: image According to this snapshot:

  1. The first metaproj was processed at 12:23:10.872 and it took over 13 minutes to process it.
  2. There are 22 entries with the reported start time falling in the first 0.5 seconds after 12:23:10.872

How is this possible at all with the concurrency level of 4? Many of the entries took over 2 minutes to run.

From the hierarchy point of view, many of them are children of the same top level node: image

The time of the first child: image

And the last one falling within the same second: image

There are certainly more than 4 children that were started, according to the log at more or less the same time.

One logical explanation could be something like this:

  1. MyDayforce.csproj.metaproj starts and immediately yields, because it depends on Framework.csproj.metaproj
  2. Framework.csproj.metaproj starts and immediately yields, because it depends on ... ...

But then we should see a hierarchical relationship between these nodes, yet they are reported flat.

What am I missing?

KirillOsenkov commented 2 years ago

Unfortunately I have no time to investigate this as this is very deep and I'm not well positioned to have a repro, etc. I don't know more about this area than you do. Just setting the expectations here.

All the viewer does is report the timestamps on ProjectStartedEventArgs and ProjectFinishedEventArgs. Those come from MSBuild. I don't know anything about .metaproj and how those are reported.

MarkKharitonov commented 2 years ago

Got it. Thank you.

KirillOsenkov commented 2 years ago

One thing I forgot to mention is that you probably have .metaproj files because your .sln specifies dependencies between projects. My recommendation is to remove that from the .sln and switch to ProjectReferences to indicate dependencies, wherever possible. Dependencies in .csproj are an obsolete feature that can cause a lot of trouble.

image

KirillOsenkov commented 2 years ago

@MarkKharitonov ^^

MarkKharitonov commented 2 years ago

@KirillOsenkov - the reason for these dependencies is that these projects contain both C# and Typescript code. The two kinds of code have completely independent build logic and dependencies. For example, project A may depend on project B from the Typescript perspective, but not from the C# perspective.

We are capturing it with the solution level dependency, because we do not want to actually couple the two projects. You have reminded me that I wanted to separate the two different kinds of code from each other, i.e. create dedicated Typescript only projects which could depend on each other. I guess this is a good opportunity to do it.

Would you happen to have any advice for me as to what kind of project to use for the Typescript? Using the csproj extension does not seem right and I definitely would not want to use the C# build targets...

KirillOsenkov commented 2 years ago

I have no idea honestly but I can ask around.

KirillOsenkov commented 2 years ago

I've asked around on Twitter: https://twitter.com/KirillOsenkov/status/1463976676182802437

They say .esproj is the current recommendation: https://devblogs.microsoft.com/visualstudio/the-new-javascript-typescript-experience-in-vs-2022-preview-3/

But also there's a prototype JavaScript.Sdk: https://www.nuget.org/packages/Microsoft.VisualStudio.JavaScript.SDK

MarkKharitonov commented 2 years ago

Much appreciated. Thank you very much.