Performance workitems hang when trying to kill build servers at shutdown

[safern]

We've seen workitems that hang trying to kill compiler servers on shutdown, and given that the workitems timeout is 4 hours, PRs just sit waiting forever and also clogging the queues.

These workitems just sit running the following command:

[2020/06/18 18:41:23][INFO] $ dotnet build-server shutdown
[2020/06/18 18:41:23][INFO] Shutting down MSBuild server...
[2020/06/18 18:41:23][INFO] Shutting down VB/C# compiler server...
[2020/06/18 18:41:23][INFO] VB/C# compiler server shut down successfully.

Maybe it is a dotnet build-server issue.

cc: @dotnet/runtime-infrastructure @DrewScoggins @billwert @adamsitnik

[Dotnet-GitSync-Bot]

I couldn't figure out the best area label to add to this issue. Please help me learn by adding exactly one area label.

[danmoseley]

I'm guessing it got as far as calling into MSBuild here
https://github.com/dotnet/sdk/blob/b1223209644d900702287faea8e9b71f95ec49f8/src/Cli/dotnet/BuildServer/MSBuildServer.cs#L18
which ultimately to connect to all dotnet processes in turn, with 2x 30 sec timeout on each
https://github.com/microsoft/msbuild/blob/93fec27d7168675a369729446ad96aaaaa84137f/src/Build/BackEnd/Components/Communications/NodeProviderOutOfProcBase.cs#L126
but I would expect it to fail immediately unless the node was MSBuild. If it connects, then it tries to read.

But, who knows what is going on -- to investigate, you should

set MSBUILDEBUGCOMM=1
set MSBUILDDEBUGPATH=<some path to put the trace>

This will immediately show what it is doing.

[danmoseley]

Possibly dotnet build-server shutdown should have its own timeout (?) but then it might increase the non determinism.

[danmoseley]

Was this Unix, or Windows? Also, could this relate to the recent twiddling of the MSBuild handshake, which led to the performance issues? If the MSBuild loaded into dotnet build-server shutdown was expecting a longer handshake than the MSBuild in the persistent node was planning to write, it could hang - but I'm totally speculating.

[danmoseley]

cc @rainersigwald in case this is familiar.

[DrewScoggins]

I will add those commands to our PR runs so we can try and track this down. @safern @MattGal is there a location I can put the log so that it automatically gets scooped up by Helix's archiving?

[safern]

That I'm not sure, @alexperovich ?

[danmoseley]

https://github.com/dotnet/arcade/blob/3bbaf862aac175fca30fc4b82fdec83d7b132f23/src/Microsoft.DotNet.RemoteExecutor/src/RemoteInvokeHandle.cs#L146

I think it's %HELIX_WORKITEM_UPLOAD_ROOT%?

[safern]

Good find @danmosemsft, that’s it: https://github.com/dotnet/arcade/blob/d91db2c6bc09f9f4a60c4e55f1addd038f9413e9/src/Microsoft.DotNet.Helix/Sdk/tools/azure-pipelines/reporter/run.py#L91

[MattGal]

Good find @danmosemsft, that’s it: https://github.com/dotnet/arcade/blob/d91db2c6bc09f9f4a60c4e55f1addd038f9413e9/src/Microsoft.DotNet.Helix/Sdk/tools/azure-pipelines/reporter/run.py#L91

Yup just make sure you adjust the environment variable syntax for OS (i.e. $ on non-Windows)

[DrewScoggins]

Great