roslyn: Very slow VS builds with cross compile

After a lot of digging around with @onovotny this appears to be a scheduling bug in a specific Windows Insider Build. Oren was kind enough to share out dumps of VBCSCompiler, MSBuild and ETL traces of VBCSCompiler which helped us track down this problem.

The Details …

Looking at the roslyn logs for the slow compilation we see the following pattern in good cases:

--- PID=36356 TID=121 Ticks=157185437: ****Running C# compiler...
--- PID=36356 TID=121 Ticks=157185468: ****C# Compilation complete.
****Return code: 0
****Output:

The PID 36356 represents VBCSCompiler and these lines are coming from CompilerRequestHandler.cs.

Log($"****Running {request.Language} compiler...");
TextWriter output = new StringWriter(CultureInfo.InvariantCulture);
int returnCode = compiler.Run(output, cancellationToken);
Log($"****{request.Language} Compilation complete.\r\n****Return code: {returnCode}\r\n****Output:\r\n{output.ToString()}\r\n")

Notice the log entries essentially bracket the core synchronous compilation APIs. This means we can use these log file entries to accurately track the start and end of compilation independent of any scheduling issues in the server.

As we would expect in the good case the compilation of the code completes quickly. But in the slow case we see the following in the log files:

--- PID=36356 TID=127 Ticks=157189750: ****Running C# compiler...
--- PID=26956 TID=6 Ticks=157234046: Before poking pipe.
--- PID=26956 TID=3 Ticks=157234046: After poking pipe.
<repeat 40+ times /> 
--- PID=36356 TID=69 Ticks=157234078: Pipe 33: Before poking pipe.
--- PID=36356 TID=46 Ticks=157234078: Pipe 33: After poking pipe.
--- PID=36356 TID=127 Ticks=157234093: ****C# Compilation complete.

This given us a lot of information. The first piece of data is that the actual compilation code is where the slow down occurs. It’s now taking ~44 seconds to compile the code where before it was < 1 second.

The second piece of data is the entire VBCSCompiler process is likely stalled / starved. Take a look at the “poking pipe” entries. Both the client and server have essentially heartbeat actions attached to the named pipe connection that fire with a granularity of one second. The MSBuild process (PID 26956) has the expected number of heart beats while the VBCSCompiler process does not. It has only one heart beat attempt and it’s immediately after the compilation succeeds.

There are a number of possible reasons for a stall that we ruled out:

• CPU starvation: The ETL files don’t show any sources of excessive CPU usage in this time period. The VBCSCompiler process is completely non-active and no other process is using significant CPU.
• I/O blocking: The compiler does have several sources of synchronous I/O which could stall a compilation (parsing response files for example). This can be ruled out as it wasn’t present in the dump files and doesn’t explain the lack of heart beat entries.
• Compiler code itself: Running csc.exe directly never hung. The log clearly pointed to compile.Run being stalled and that is shared code between VBCSCompiler and csc. It’s likely, but not guaranteed, that if one hung the other should too.

The final piece of data though was upgrading to a new insider build, Win10 14986, caused the issue to stop reproducing. So as reluctant as I am to say “it’s an OS bug” the data seems to point that way.

Thanks to @onovotny for helping us investigate this. Basically impossible to investigate this type of bug without a lot of customer help.