Runtime: 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.

[danmosemsft]

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.

[danmosemsft]

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

[danmosemsft]

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.

[danmosemsft]

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 ?

[danmosemsft]

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

[rainersigwald]

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]

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.

[msftbot[bot]]

Tagging subscribers to this area: @ViktorHofer
Notify danmosemsft if you want to be subscribed.

[danmosemsft]

@Forgind would that lead to a hang though? Would the "server" MSBuild be left hanging because it didn't get enough bytes, for example?

[Forgind]

I don't think so, but I might be wrong. As I understand it, the child will disconnect if the parent's handshake doesn't match, which will cause the parent to stop waiting. If the parent's handshake matches, the client handshake should match, since it's just the opposite of the host handshake. Maybe if there's a critical exception in the node client, it wouldn't disconnect properly? The number of bytes shouldn't have changed recently, since although the handshake changed, it was a long before and a long after.

[danmosemsft]

@Forgind i had the same conclusion so we need the logs.

[danmosemsft]

Any hits with the new logging?

[safern]

I think I saw a hit yesterday, will look around.

[DrewScoggins]

OK, the logs should just be part of the files uploaded as part of Helix.

[safern]

Found a couple of instances but I don't see the MSBuild logs:

https://helix.dot.net/api/2019-06-17/jobs/d2e4e8b6-347a-43c9-bed1-f0142f1545f0/workitems/x64.micro_mono.net5.0.Partition24/files
https://helix.dot.net/api/2019-06-17/jobs/d2e4e8b6-347a-43c9-bed1-f0142f1545f0/workitems/x64.micro_mono.net5.0.Partition24/console

https://helix.dot.net/api/2019-06-17/jobs/bdb31774-f89d-41ee-ac8b-5ae7fc309218/workitems/x64.micro_mono.net5.0.Partition5/files
https://helix.dot.net/api/2019-06-17/jobs/bdb31774-f89d-41ee-ac8b-5ae7fc309218/workitems/x64.micro_mono.net5.0.Partition5/console

The file list only contains the console logs.

[DrewScoggins]

When I put the logging in I only put it in for internal runs, not CI runs. Can you find any examples of this issue on our physical perf queues? They are ubuntu.1804.amd64.tiger.perf and windows.10.amd64.19h1.tiger.perf

[safern]

When I put the logging in I only put it in for internal runs, not CI runs. Can you find any examples of this issue on our physical perf queues?

It would be nice to put it in CI runs as well if we can as those are the ones that are impacting developer productivity by failing the build because of this.

[safern]

Here is one: https://dev.azure.com/dnceng/internal/_build/results?buildId=723725&view=ms.vss-test-web.build-test-results-tab&runId=22403688&resultId=100026&paneView=attachments

[DrewScoggins]

It looks like all of the timeouts on the internal side are unrelated. I will add this logging to the CI runs as well so we can track this down.

[safern]

Sounds good.

[safern]

It seems like this is happening a lot now.

[danmosemsft]

https://github.com/dotnet/runtime/pull/39217#issuecomment-657897621

[DrewScoggins]

I was off today. I will take a look at this tomorrow morning.

[ViktorHofer]

any update on this? Are the work items still hanging?

[DrewScoggins]

I have been working on a bunch of 3.1->5.0 perf comparison work so I have not gotten around to adding the additional logging that we need here. I believe that @safern was still seeing some hangs.

[safern]

I've seen this in a lot of jobs so adding the logging is important. Could you help us add the logging or point us where we can add it?

[ViktorHofer]

We should fix this asap, otherwise we probably need to disable the leg.

[safern]

Yeah I agree. We should enable the logs today ASAP before disabling the legs to get some logs and so that MSBuild can investigate.

[danmosemsft]

+1 to @safern comment.

[billwert]

Just started #39381 to address this. Once it's merged we should always have logs.

[billwert]

Just merged the logging fix.

[danmosemsft]

Thanks. Once we have the logs, if the job is unstable we should disable it until we have a fix.

[safern]

We just hit this:
https://dev.azure.com/dnceng/public/_build/results?buildId=740369&view=results

https://helix.dot.net/api/2019-06-17/jobs/9648d2d9-73e9-422c-a883-accac6f7badb/workitems/release.Partition19/files/MSBuild_CommTrace_PID_26670.txt
https://helix.dot.net/api/2019-06-17/jobs/9648d2d9-73e9-422c-a883-accac6f7badb/workitems/release.Partition19/files/MSBuild_CommTrace_PID_27745.txt
https://helix.dot.net/api/2019-06-17/jobs/9648d2d9-73e9-422c-a883-accac6f7badb/workitems/release.Partition19/files/MSBuild_CommTrace_PID_26645.txt

[DrewScoggins]

Here is another instance of this.

https://helix.dot.net/api/2019-06-17/jobs/8ead7b32-0a3b-439d-a3f2-902b8b23fed5/workitems/release.Partition18/files/MSBuild_CommTrace_PID_16652.txt

https://helix.dot.net/api/2019-06-17/jobs/8ead7b32-0a3b-439d-a3f2-902b8b23fed5/workitems/release.Partition18/files/MSBuild_CommTrace_PID_14970.txt

https://helix.dot.net/api/2019-06-17/jobs/8ead7b32-0a3b-439d-a3f2-902b8b23fed5/workitems/release.Partition18/files/MSBuild_CommTrace_PID_14995.txt

[safern]

@Forgind @rainersigwald is this enough for the investigation?

[danmosemsft]

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 have ShutdownAllNodes() 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:false or environment variable MSBUILDDISABLENODEREUSE=1). It seems to be happening only on Unix. Otherwise, disable the legs.

[DrewScoggins]

OK, we can add the node reuse disable for now.

[Forgind]

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]

@DrewScoggins @safern what's the status on this?

[safern]

Let's keep this in 5.0.0 as I think it should be prioritized, since it is blocking clean CI.

Are those the only three traces for each case there are?

Yeah @Forgind those are the only logs that we found in the computer, is there another way we can get more logs for this?

[danmosemsft]

@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.

[danmosemsft]

@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]

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.

[danmosemsft]

Sounds good, thanks @billwert . Experiments are good!