Over the past few weeks we've added the ability to capture process dumps to the build. (Currently for Windows Test and Windows Templates Test).
When a build hangs on the CI, a process dump is captured for currently running processes. (we capture dumps for dotnet processes, but can be easily expanded to other processes)
These dumps are available as artifacts under Artifacts -> Windows_Test_Dumps and Artifacts -> Windows_Templates_Test_Dumps respectively.
It just happened that right after adding support for capturing dumps on hanging builds, we got a chance to try it out. Our merge branch from 3.1 to master was causing the Template tests builds to hang.
With the new infrastructure, we opened the current build in Azure DevOps. Opened artifacts -> Windows_Templates_Test_Dumps and downloaded the dump (hung_dotnet.exe_....dmp).
There are several ways to analyze a process dump. The classical ways to do this are Wind DBG and the Visual Studio Debugger. There is a new tool "dotnet dump" that also allows you do analyze dumps.
In my case I used Win DBG. To do this, I started by opening the process dump in Win DBG. After opening the dump in Win DBG, the SOS extension should be loaded automatically, but if that is not the case, you can install "dotnet sos" and then run dotnet sos install to provision the sos extension. The tool will tell you to load sos in the debugger by running .load C:\Users\<<user>>\.dotnet\sos\sos.dll
After loading the sos extension we have a bunch of commands avalable to help diagnosing what is happening. Given that it is a hang, we are interested in what the app is doing. We can look at the threads in the app with !DumpStack or !DumpStack -ee to list only the managed threads. An example of the output is:
0:000> !DumpStack -ee
OS Thread Id: 0x23a8 (0)
Current frame:
Child-SP RetAddr Caller, Callee
000000F60D17E220 00007ff8ff0e0064 (MethodDesc 00007ff8a4414710 + 0x54 System.Threading.WaitHandle.WaitOneNoCheck(Int32))
000000F60D17E2F0 00007ff8ff0e0064 (MethodDesc 00007ff8a4414710 + 0x54 System.Threading.WaitHandle.WaitOneNoCheck(Int32))
000000F60D17E320 00007ff8a4608d68 (MethodDesc 00007ff8a43c97a0 + 0x28 Xunit.DelegatingXmlCreationSink.get_Finished())
000000F60D17E350 00007ff8a42a55cf (MethodDesc 00007ff8a4157648 + 0x8ff Xunit.ConsoleClient.ConsoleRunner.ExecuteAssembly(System.Object, Xunit.XunitProjectAssembly, Boolean, Boolean, System.Nullable`1<Boolean>, System.Nullable`1<Int32>, Boolean, Boolean, System.Nullable`1<Xunit.AppDomainSupport>, Boolean, Boolean, Xunit.XunitFilters, Boolean))
000000F60D17E490 00007ff8a42a2071 (MethodDesc 00007ff8a4157630 + 0x621 Xunit.ConsoleClient.ConsoleRunner.RunProject(Xunit.XunitProject, Boolean, System.Nullable`1<Boolean>, System.Nullable`1<Boolean>, System.Nullable`1<Int32>, Boolean, Boolean, System.Nullable`1<Xunit.AppDomainSupport>, Boolean, Boolean, Boolean))
000000F60D17E540 00007ff8a42a1ba0 (MethodDesc 00007ff8a4157630 + 0x150 Xunit.ConsoleClient.ConsoleRunner.RunProject(Xunit.XunitProject, Boolean, System.Nullable`1<Boolean>, System.Nullable`1<Boolean>, System.Nullable`1<Int32>, Boolean, Boolean, System.Nullable`1<Xunit.AppDomainSupport>, Boolean, Boolean, Boolean))
000000F60D17E680 00007ff8a40ac39a (MethodDesc 00007ff8a41575d0 + 0x4ba Xunit.ConsoleClient.ConsoleRunner.EntryPoint(System.String[]))
000000F60D17E820 00007ff8a4081849 (MethodDesc 00007ff8a4122448 + 0x109 Xunit.ConsoleClient.Program.Main(System.String[]))
The output from this command tells us what the current threads are doing (running or blocked). This gives us an idea, but doesn't provide the full picture. To get that, we can use another command !DumpAsync. DumpAsync traverses the heap and displays all the async stacks and where they are. An example of the output is
0:000> !DumpAsync
Statistics:
MT Count TotalSize Class Name
00007ff8a47321e8 1 128 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[Xunit.Sdk.RunSummary, xunit.core],[Xunit.Sdk.TestMethodRunner`1+<RunAsync>d__31[[Xunit.Sdk.IXunitTestCase, xunit.core]], xunit.execution.dotnet]]
00007ff8a470f278 1 128 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Tuple`2[[System.Decimal, System.Private.CoreLib],[System.String, System.Private.CoreLib]], System.Private.CoreLib],[Xunit.Sdk.ExceptionAggregator+<RunAsync>d__10`1[[System.Tuple`2[[System.Decimal, System.Private.CoreLib],[System.String, System.Private.CoreLib]], System.Private.CoreLib]], xunit.core]]
00007ff8a470cb48 1 128 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Xunit.Sdk.ExceptionAggregator+<RunAsync>d__9, xunit.core]]
00007ff8a470c200 1 128 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Xunit.Sdk.TestInvoker`1+<>c__DisplayClass48_1+<<InvokeTestMethodAsync>b__1>d[[Xunit.Sdk.IXunitTestCase, xunit.core]], xunit.execution.dotnet]]
00007ff8a473b048 1 136 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[Xunit.Sdk.RunSummary, xunit.core],[Xunit.Sdk.TestCollectionRunner`1+<RunAsync>d__27[[Xunit.Sdk.IXunitTestCase, xunit.core]], xunit.execution.dotnet]]
00007ff8a4735458 1 136 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[Xunit.Sdk.RunSummary, xunit.core],[Xunit.Sdk.TestClassRunner`1+<RunAsync>d__37[[Xunit.Sdk.IXunitTestCase, xunit.core]], xunit.execution.dotnet]]
00007ff8a4730990 1 136 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[Xunit.Sdk.RunSummary, xunit.core],[Xunit.Sdk.TestCaseRunner`1+<RunAsync>d__19[[Xunit.Sdk.IXunitTestCase, xunit.core]], xunit.execution.dotnet]]
00007ff8a470e160 1 136 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Decimal, System.Private.CoreLib],[Xunit.Sdk.ExceptionAggregator+<RunAsync>d__10`1[[System.Decimal, System.Private.CoreLib]], xunit.core]]
00007ff8a470c768 1 136 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Xunit.Sdk.ExecutionTimer+<AggregateAsync>d__4, xunit.execution.dotnet]]
00007ff8a4ab9828 1 144 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[Templates.Test.Helpers.ProcessEx, ProjectTemplates.Tests],[Templates.Test.Helpers.ProcessEx+<RunViaShellAsync>d__24, ProjectTemplates.Tests]]
00007ff8a4737aa0 1 144 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[Xunit.Sdk.RunSummary, xunit.core],[Xunit.Sdk.TestCollectionRunner`1+<RunTestClassesAsync>d__28[[Xunit.Sdk.IXunitTestCase, xunit.core]], xunit.execution.dotnet]]
00007ff8a4731680 1 144 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[Xunit.Sdk.RunSummary, xunit.core],[Xunit.Sdk.TestMethodRunner`1+<RunTestCasesAsync>d__32[[Xunit.Sdk.IXunitTestCase, xunit.core]], xunit.execution.dotnet]]
00007ff8a470f9a8 1 144 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[Xunit.Sdk.RunSummary, xunit.core],[Xunit.Sdk.TestRunner`1+<RunAsync>d__43[[Xunit.Sdk.IXunitTestCase, xunit.core]], xunit.execution.dotnet]]
00007ff8a470e8f0 1 144 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Tuple`2[[System.Decimal, System.Private.CoreLib],[System.String, System.Private.CoreLib]], System.Private.CoreLib],[Xunit.Sdk.XunitTestRunner+<InvokeTestAsync>d__4, xunit.execution.dotnet]]
00007ff8a470d728 1 144 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Decimal, System.Private.CoreLib],[Xunit.Sdk.TestInvoker`1+<InvokeTestMethodAsync>d__48[[Xunit.Sdk.IXunitTestCase, xunit.core]], xunit.execution.dotnet]]
00007ff8a4733cf0 1 152 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[Xunit.Sdk.RunSummary, xunit.core],[Xunit.Sdk.TestClassRunner`1+<RunTestMethodsAsync>d__38[[Xunit.Sdk.IXunitTestCase, xunit.core]], xunit.execution.dotnet]]
00007ff8a470deb8 1 152 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Decimal, System.Private.CoreLib],[Xunit.Sdk.TestInvoker`1+<<RunAsync>b__47_0>d[[Xunit.Sdk.IXunitTestCase, xunit.core]], xunit.execution.dotnet]]
00007ff8a46b3f40 1 160 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Microsoft.AspNetCore.E2ETesting.XunitTestFrameworkExecutorWithAssemblyFixture+<RunTestCases>d__1, ProjectTemplates.Tests]]
00007ff8a46b3650 1 160 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[Xunit.Sdk.RunSummary, xunit.core],[Xunit.Sdk.TestAssemblyRunner`1+<RunAsync>d__41[[Xunit.Sdk.IXunitTestCase, xunit.core]], xunit.execution.dotnet]]
00007ff8a4a0b638 1 224 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Templates.Test.SpaTemplateTest.SpaTemplateTestBase+<SpaTemplateImplAsync>d__9, ProjectTemplates.Tests]]
00007ff8a46b1338 1 224 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[Xunit.Sdk.RunSummary, xunit.core],[Xunit.Sdk.XunitTestAssemblyRunner+<RunTestCollectionsAsync>d__14, xunit.execution.dotnet]]
00007ff8a47b8788 4 512 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[System.Diagnostics.AsyncStreamReader+<ReadBufferAsync>d__16, System.Diagnostics.Process]]
Total 25 objects
Address MT Size State Description
0000029ab6eae6b0 00007ff8a46b1338 224 1 Xunit.Sdk.XunitTestAssemblyRunner+<RunTestCollectionsAsync>d__14
0000029ab6eae7d0 00007ff8a46b3650 160 1 Xunit.Sdk.TestAssemblyRunner`1+<RunAsync>d__41[[System.__Canon, System.Private.CoreLib]]
0000029ab6eae870 00007ff8a46b3f40 160 0 Microsoft.AspNetCore.E2ETesting.XunitTestFrameworkExecutorWithAssemblyFixture+<RunTestCases>d__1
0000029ab6edc398 00007ff8a47b8788 128 0 System.Diagnostics.AsyncStreamReader+<ReadBufferAsync>d__16
0000029ab6edf5d8 00007ff8a470deb8 152 2 Xunit.Sdk.TestInvoker`1+<<RunAsync>b__47_0>d[[System.__Canon, System.Private.CoreLib]]
0000029ab6edf6b0 00007ff8a470e160 136 0 Xunit.Sdk.ExceptionAggregator+<RunAsync>d__10`1[[System.Decimal, System.Private.CoreLib]]
0000029ab6edf7a8 00007ff8a470e8f0 144 0 Xunit.Sdk.XunitTestRunner+<InvokeTestAsync>d__4
0000029ab6edf8a8 00007ff8a470f278 128 0 Xunit.Sdk.ExceptionAggregator+<RunAsync>d__10`1[[System.__Canon, System.Private.CoreLib]]
0000029ab6edf998 00007ff8a470f9a8 144 0 Xunit.Sdk.TestRunner`1+<RunAsync>d__43[[System.__Canon, System.Private.CoreLib]]
0000029ab6edfa98 00007ff8a4730990 136 1 Xunit.Sdk.TestCaseRunner`1+<RunAsync>d__19[[System.__Canon, System.Private.CoreLib]]
0000029ab6edfb90 00007ff8a4731680 144 0 Xunit.Sdk.TestMethodRunner`1+<RunTestCasesAsync>d__32[[System.__Canon, System.Private.CoreLib]]
0000029ab6edfc90 00007ff8a47321e8 128 0 Xunit.Sdk.TestMethodRunner`1+<RunAsync>d__31[[System.__Canon, System.Private.CoreLib]]
0000029ab6edfd80 00007ff8a4733cf0 152 0 Xunit.Sdk.TestClassRunner`1+<RunTestMethodsAsync>d__38[[System.__Canon, System.Private.CoreLib]]
0000029ab6edfe88 00007ff8a4735458 136 1 Xunit.Sdk.TestClassRunner`1+<RunAsync>d__37[[System.__Canon, System.Private.CoreLib]]
0000029ab6edff80 00007ff8a4737aa0 144 0 Xunit.Sdk.TestCollectionRunner`1+<RunTestClassesAsync>d__28[[System.__Canon, System.Private.CoreLib]]
0000029ab6ee0080 00007ff8a473b048 136 1 Xunit.Sdk.TestCollectionRunner`1+<RunAsync>d__27[[System.__Canon, System.Private.CoreLib]]
0000029ab6ee7388 00007ff8a47b8788 128 0 System.Diagnostics.AsyncStreamReader+<ReadBufferAsync>d__16
0000029ab6f77698 00007ff8a4a0b638 224 4 Templates.Test.SpaTemplateTest.SpaTemplateTestBase+<SpaTemplateImplAsync>d__9
0000029ab6f777b8 00007ff8a470c200 128 0 Xunit.Sdk.TestInvoker`1+<>c__DisplayClass48_1+<<InvokeTestMethodAsync>b__1>d[[System.__Canon, System.Private.CoreLib]]
0000029ab6f778a8 00007ff8a470c768 136 0 Xunit.Sdk.ExecutionTimer+<AggregateAsync>d__4
0000029ab6f779a0 00007ff8a470cb48 128 0 Xunit.Sdk.ExceptionAggregator+<RunAsync>d__9
0000029ab6f77a90 00007ff8a470d728 144 0 Xunit.Sdk.TestInvoker`1+<InvokeTestMethodAsync>d__48[[System.__Canon, System.Private.CoreLib]]
0000029ab704aa70 00007ff8a47b8788 128 0 System.Diagnostics.AsyncStreamReader+<ReadBufferAsync>d__16
0000029ab70a99c8 00007ff8a47b8788 128 0 System.Diagnostics.AsyncStreamReader+<ReadBufferAsync>d__16
0000029ab70caa20 00007ff8a4ab9828 144 0 Templates.Test.Helpers.ProcessEx+<RunViaShellAsync>d__24
From the async dumps we can search for our code. We can see it in
00007ff8a4ab9828 1 144 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[Templates.Test.Helpers.ProcessEx, ProjectTemplates.Tests],[Templates.Test.Helpers.ProcessEx+<RunViaShellAsync>d__24, ProjectTemplates.Tests]]
00007ff8a4a0b638 1 224 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Templates.Test.SpaTemplateTest.SpaTemplateTestBase+<SpaTemplateImplAsync>d__9, ProjectTemplates.Tests]]
and
0000029ab6f77698 00007ff8a4a0b638 224 4 Templates.Test.SpaTemplateTest.SpaTemplateTestBase+<SpaTemplateImplAsync>d__9
0000029ab70caa20 00007ff8a4ab9828 144 0 Templates.Test.Helpers.ProcessEx+<RunViaShellAsync>d__24
The fist table gives us the a count of the async state machines the c# compiler generates when you use async/await. The second table gives us details about each of the state machines, like the size or their state.
The important field to look at is the "state" field. When the code uses async/await, it creates a state machine and uses a 'state' field to track where it is in the execution of the async method. There are several known numbers:
- -1 is the initial state for the machine, that means the code didn't even start running.
- -N is the final state for the machine, that means the code finished executing. N is the number of awaits in the async method + 1.
- 0..N represents the current execution state for the given async state machine. Starting from 0 which represents the code block before the first await statement.
We can translate this to our example as follows.
- We can locate the method by looking at
Templates.Test.SpaTemplateTest.SpaTemplateTestBase+<SpaTemplateImplAsync>which tells us is this method https://github.com/aspnet/AspNetCore/blob/master/src/ProjectTemplates/test/SpaTemplateTest/SpaTemplateTestBase.cs#L39 - From there, we can see that the state is 4 so looking at the code for the method
protected async Task SpaTemplateImplAsync(
string key,
string template,
bool useLocalDb = false,
bool usesAuth = false)
{
// State = 0
Project = await ProjectFactory.GetOrCreateProject(key, Output);
// State = 1
using var createResult = await Project.RunDotNetNewAsync(template, auth: usesAuth ? "Individual" : null, language: null, useLocalDb);
// State = 2
Assert.True(0 == createResult.ExitCode, ErrorMessages.GetFailedProcessMessage("create/restore", Project, createResult));
var clientAppSubdirPath = Path.Combine(Project.TemplateOutputDir, "ClientApp");
ValidatePackageJson(clientAppSubdirPath);
var projectFileContents = ReadFile(Project.TemplateOutputDir, $"{Project.ProjectName}.csproj");
if (usesAuth && !useLocalDb)
{
Assert.Contains(".db", projectFileContents);
}
using var npmRestoreResult = await Project.RestoreWithRetryAsync(Output, clientAppSubdirPath);
// State = 3
Assert.True(0 == npmRestoreResult.ExitCode, ErrorMessages.GetFailedProcessMessage("npm restore", Project, npmRestoreResult));
using var lintResult = await ProcessEx.RunViaShellAsync(Output, clientAppSubdirPath, "npm run lint");
// State = 4
Assert.True(0 == lintResult.ExitCode, ErrorMessages.GetFailedProcessMessage("npm run lint", Project, lintResult));
var testResult = await ProcessEx.RunViaShellAsync(Output, clientAppSubdirPath, "npm run test");
// State = 5
Assert.True(0 == testResult.ExitCode, ErrorMessages.GetFailedProcessMessage("npm run test", Project, testResult));
.
.
.
As we can see from the debug session, the state is set on 4, which means that the execution never resumes after invoking var testResult = await ProcessEx.RunViaShellAsync(Output, clientAppSubdirPath, testcommand);
If we pay a little attention to our debug session we see that there is another async state machine RunViaShellAsync:
0000029ab70caa20 00007ff8a4ab9828 144 0 Templates.Test.Helpers.ProcessEx+<RunViaShellAsync>d__24
We can look at the code for the method and apply the same reasoning
https://github.com/aspnet/AspNetCore/blob/master/src/ProjectTemplates/test/Helpers/ProcessEx.cs#L107-L115
public static async Task<ProcessEx> RunViaShellAsync(ITestOutputHelper output, string workingDirectory, string commandAndArgs)
{
// State 0
var (shellExe, argsPrefix) = RuntimeInformation.IsOSPlatform(OSPlatform.Windows)
? ("cmd", "/c")
: ("bash", "-c");
var result = Run(output, workingDirectory, shellExe, $"{argsPrefix} \"{commandAndArgs}\"");
await result.Exited;
// State 1
return result;
We can see that the execution is never resuming from the call to await result.exited. At this point we have a clear picture of where the build is hanging and we can troubleshoot the issue. To do this we can do a few things, but in the general case there is no silver bullet:
- Try to repro the issue locally. Run the test and see if it hangs in your environment.
- Try and skip the affected code and see if that avoids the issue.
- If you are merging a branch, check the differences between the existing code and the code in the branch you are merging to.
In our particular case, the issue happened to repro locally, and it was caused by a change introduced in the master branch to reenable running the client tests for the angular template. Essentially the tests will run by default in watch mode and the process would never finish. I was able to find this by comparing the code in the 3.1 and 5.0 branches. Once that was determined, a bit of googling gave me the key to the solution, which was simply to pass "--watch false" to "ng test".
var testcommand = "npm run test" + template == "angular" ? "-- --watch=false" : "";
var testResult = await ProcessEx.RunViaShellAsync(Output, clientAppSubdirPath, testcommand);
With the fix in place, I ran the build locally and on the CI and got the build to run to completion and the tests to pass.
- Debugging a build hang might seem like an impossible task, but it is actually doable if you capture the right information and use the right tools for it.
- Knowing the inner workings of .NET will go a long way towards helping you troubleshoot these types of issues.
- The first time I did this, it took me, Pavel and Stephen a good couple of days to find what was going on. This time, it took me about 15 min to find the issue.
- I hope that by sharing this analysis with you it can help in debugging future issues.
- The advantage of using the techniques I showcased here is that they work locally and remotely. I used ProcDump to capture the dump, but there are other tools that can be used to do the same thing, like
dotnet dumpor right click on the process in Task manager and select Create dump file.
Some tips:
!DumpAsync -stacks