Repository navigation
Performance workitems hang when trying to kill build servers at shutdown #38138
Description
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
Activity
Dotnet-GitSync-Bot commentedon Jun 19, 2020
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 commentedon Jun 19, 2020
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
This will immediately show what it is doing.
danmoseley commentedon Jun 19, 2020
Possibly
dotnet build-server shutdownshould have its own timeout (?) but then it might increase the non determinism.danmoseley commentedon Jun 19, 2020
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 shutdownwas expecting a longer handshake than the MSBuild in the persistent node was planning to write, it could hang - but I'm totally speculating.danmoseley commentedon Jun 19, 2020
cc @rainersigwald in case this is familiar.
DrewScoggins commentedon Jun 19, 2020
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 commentedon Jun 19, 2020
That I'm not sure, @alexperovich ?
danmoseley commentedon Jun 20, 2020
https://github.com/dotnet/arcade/blob/3bbaf862aac175fca30fc4b82fdec83d7b132f23/src/Microsoft.DotNet.RemoteExecutor/src/RemoteInvokeHandle.cs#L146
I think it's
%HELIX_WORKITEM_UPLOAD_ROOT%?safern commentedon Jun 20, 2020
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 commentedon Jun 22, 2020
Yup just make sure you adjust the environment variable syntax for OS (i.e. $ on non-Windows)
DrewScoggins commentedon Jun 22, 2020
Great
rainersigwald commentedon Jun 23, 2020
Would it be possible to get a list of all running processes at the point of the hang? The handshake changes may be related but I hope they aren't.
cc @Forgind
Forgind commentedon Jun 23, 2020
What MSBuild version did you use? We just merged a change to the handshake that would prevent MSBuild from making too many connections, but if it's from before we masked out the first byte, that version could make too few connections and fail to shut down all MSBuild nodes.
31 remaining items
danmoseley commentedon Jul 22, 2020
Nothing jumps out to my eyes, but MSBuild folks know these logs better.
If they don't see it, I suggest
Add more logging, possibly to
dotnet build(MSBuildServer.cs eg) as well as to MSBuild eg haveShutdownAllNodes()log that it's entering, and list off each process it finds as it goes to connect to it.Change the logging to add UTC times, so they can be correlated with each other and the Azdo log more easily.
While we wait for better logging, @billwert @DrewScoggins I suggest you disable node reuse for these legs. (
/nr:falseor environment variableMSBUILDDISABLENODEREUSE=1). It seems to be happening only on Unix. Otherwise, disable the legs.DrewScoggins commentedon Jul 22, 2020
OK, we can add the node reuse disable for now.
Forgind commentedon Jul 22, 2020
Are those the only three traces for each case there are? They mention trying to connect to a lot of other processes, which sounds strange to me if those processes don't exist. On the other hand, it seems that the connection was successful with the one worker node that managed to leave a trace, and it looks like it shut down afterwards.
ViktorHofer commentedon Aug 4, 2020
@DrewScoggins @safern what's the status on this?
safern commentedon Aug 4, 2020
Let's keep this in 5.0.0 as I think it should be prioritized, since it is blocking clean CI.
Yeah @Forgind those are the only logs that we found in the computer, is there another way we can get more logs for this?
danmoseley commentedon Aug 7, 2020
@DrewScoggins @billwert this hung again. I'm not seeing activity here. Is it possible to please disable this leg today, or I can ask someone to do it.
danmoseley commentedon Aug 7, 2020
@DrewScoggins do you or anyone else plan to investigate this further, or open an issue against MSBuild with the info we have gathered? If not, I will close this and we can reopen if it becomes relevant again.
billwert commentedon Aug 7, 2020
At this point we're going to stop. We enabled this leg optimistically, not having had an actual problem but because it seemed like a good idea. Since it has proven so problematic (and for little real gain) it's not worth continuing to try and fix. Should we wind up with a huge influx of issues this would have caught we will revisit it.
danmoseley commentedon Aug 7, 2020
Sounds good, thanks @billwert . Experiments are good!