Add WinDBG extension: AsyncDebugTools

.appveyor.yml

@@ -18,10 +18,14 @@ environment:
   VisualStudioVersion: 15.0
   TreatWarningsAsErrors: true
   CodeAnalysisTreatWarningsAsErrors: true
+install:
+  appveyor DownloadFile https://dist.nuget.org/win-x86-commandline/v4.6.1/nuget.exe
 before_build:
-  msbuild src\Microsoft.VisualStudio.Threading.sln /nologo /m /v:quiet /t:restore
+  nuget restore src
 build_script:
-- msbuild src\Microsoft.VisualStudio.Threading.sln /nologo /m /fl /v:minimal /t:build,pack
+- msbuild src\Microsoft.VisualStudio.Threading.sln /p:platform="Any CPU" /nologo /m /v:minimal /t:build,pack /bl:msbuild.binlog
+- msbuild src\Microsoft.VisualStudio.Threading.sln /p:platform=x64 /nologo /m /v:minimal /bl:msbuild_x64.binlog
+- msbuild src\Microsoft.VisualStudio.Threading.sln /p:platform=x86 /nologo /m /v:minimal /bl:msbuild_x86.binlog
 test_script:
 - >-
     md "bin\%configuration%"
@@ -64,7 +68,11 @@ test_script:
 artifacts:
 - path: bin\**\*.nupkg
   name: NuGet Package
-- path: msbuild.log
-  name: Build log
+- path: bin\AsyncDebugTools\x64\$(Configuration)\AsyncDebugTools.dll
+  name: WinDbg extension (x64)
+- path: bin\AsyncDebugTools\x86\$(Configuration)\AsyncDebugTools.dll
+  name: WinDbg extension (x86)
+- path: msbuild*.binlog
+  name: Build logs
 - path: bin\**\testresults*
   name: Test results

.vsts-ci.yml

@@ -26,12 +26,19 @@ steps:
   displayName: Purge package caches
   condition: and(succeeded(), ne(variables['Hosted'], 'true'))
 
+- task: NuGetToolInstaller@0
+  displayName: Pin nuget.exe version
+  inputs:
+    versionSpec: 4.6.1
+
 - task: MicroBuildIBCMergePlugin@0
+  displayName: MicroBuild IBCMerge Plugin
   inputs:
     branch: lab/vsuvscore
   condition: and(succeeded(), ne(variables['Hosted'], 'true'))
 
 - task: MicroBuildSigningPlugin@1
+  displayName: MicroBuild Signing Plugin
   inputs:
     signType: $(SignType)
     esrpSigning: true
@@ -41,18 +48,34 @@ steps:
   inputs:
     restoreSolution: '**\*.sln'
     feedsToUse: config
-    nugetConfigPath: nuget.config
   displayName: Nuget restore packages
 
 - task: VSBuild@1
   inputs:
     vsVersion: 15.0
     msbuildArgs: /t:build,pack /m /bl:"$(Build.ArtifactStagingDirectory)/build_logs/msbuild.binlog"
-    platform: $(BuildPlatform)
+    platform: Any CPU
     configuration: $(BuildConfiguration)
   displayName: Build Visual Studio solution
 
+- task: VSBuild@1
+  inputs:
+    vsVersion: 15.0
+    msbuildArgs: /t:build /m /bl:"$(Build.ArtifactStagingDirectory)/build_logs/msbuild_x86.binlog"
+    platform: x86
+    configuration: $(BuildConfiguration)
+  displayName: Build AsyncDebugTools x86
+
+- task: VSBuild@1
+  inputs:
+    vsVersion: 15.0
+    msbuildArgs: /t:build /m /bl:"$(Build.ArtifactStagingDirectory)/build_logs/msbuild_x64.binlog"
+    platform: x64
+    configuration: $(BuildConfiguration)
+  displayName: Build AsyncDebugTools x64
+
 - task: MicroBuildCleanup@1
+  displayName: MicroBuild Cleanup
   condition: succeededOrFailed()
 
 ## The rest of these steps are for deployment and skipped for PR builds
@@ -65,48 +88,66 @@ steps:
 #  condition: and(succeeded(), ne(variables['Build.Reason'], 'PullRequest'))
 
 - task: PublishBuildArtifacts@1
+  displayName: Publish build_logs
   inputs:
     PathtoPublish: $(Build.ArtifactStagingDirectory)/build_logs
     ArtifactName: build_logs
     ArtifactType: Container
   condition: succeededOrFailed()
 
 - task: CopyFiles@1
+  displayName: Collecting symbols artifacts
   inputs:
     SourceFolder: bin
     Contents: |
       Microsoft.VisualStudio.Threading/$(BuildConfiguration)/**/Microsoft.VisualStudio.Threading.dll
       Microsoft.VisualStudio.Threading/$(BuildConfiguration)/**/Microsoft.VisualStudio.Threading.pdb
       Microsoft.VisualStudio.Threading.Analyzers/$(BuildConfiguration)/**/Microsoft.VisualStudio.Threading.Analyzers.dll
       Microsoft.VisualStudio.Threading.Analyzers/$(BuildConfiguration)/**/Microsoft.VisualStudio.Threading.Analyzers.pdb
+      AsyncDebugTools/x86/$(BuildConfiguration)/AsyncDebugTools.dll
+      AsyncDebugTools/x86/$(BuildConfiguration)/AsyncDebugTools.pdb
+      AsyncDebugTools/x64/$(BuildConfiguration)/AsyncDebugTools.dll
+      AsyncDebugTools/x64/$(BuildConfiguration)/AsyncDebugTools.pdb
     TargetFolder: $(Build.ArtifactStagingDirectory)/symbols
-  displayName: Collecting symbols artifacts
   condition: and(succeeded(), ne(variables['Build.Reason'], 'PullRequest'))
 
 - task: PublishBuildArtifacts@1
+  displayName: Publish symbols
   inputs:
     PathtoPublish: $(Build.ArtifactStagingDirectory)/symbols
     ArtifactName: symbols
     ArtifactType: Container
   condition: and(succeeded(), ne(variables['Build.Reason'], 'PullRequest'))
 
 - task: CopyFiles@1
+  displayName: Collecting deployable packages
   inputs:
     Contents: |
       bin/**/$(BuildConfiguration)/**/*.nupkg
     TargetFolder: $(Build.ArtifactStagingDirectory)/deployables
     flattenFolders: true
-  displayName: Collecting deployables
+  condition: and(succeeded(), ne(variables['Build.Reason'], 'PullRequest'))
+
+- task: CopyFiles@1
+  displayName: Collecting deployable binaries
+  inputs:
+    Contents: |
+      x86/$(BuildConfiguration)/AsyncDebugTools.dll
+      x64/$(BuildConfiguration)/AsyncDebugTools.dll
+    SourceFolder: bin/AsyncDebugTools
+    TargetFolder: $(Build.ArtifactStagingDirectory)/deployables
   condition: and(succeeded(), ne(variables['Build.Reason'], 'PullRequest'))
 
 - task: PublishBuildArtifacts@1
+  displayName: Publish deployables
   inputs:
     PathtoPublish: $(Build.ArtifactStagingDirectory)/deployables
     ArtifactName: deployables
     ArtifactType: Container
   condition: and(succeeded(), ne(variables['Build.Reason'], 'PullRequest'))
 
 - task: PublishSymbols@2
+  displayName: Archive symbols
   inputs:
     SymbolsFolder: $(Build.ArtifactStagingDirectory)/symbols
     SearchPattern: '**/*.pdb'
@@ -115,6 +156,7 @@ steps:
   condition: and(succeeded(), ne(variables['Build.Reason'], 'PullRequest'))
 
 - task: NuGetCommand@2
+  displayName: Push NuGet packages
   inputs:
     command: push
     searchPatternPush: '$(Build.SourcesDirectory)\bin\**\$(BuildConfiguration)\**\*.nupkg;!**\*.symbols.nupkg;!**/VS.*.nupkg'

doc/async_hang.md

@@ -0,0 +1,31 @@
+# Async hang investigations
+
+An "asynchronous hang" is one in which the UI thread is synchronously blocked waiting for an asynchronous operation to complete. Because the operation is an async one, the callstack for operation that must complete to resolve the hang may not be evident on the UI thread or any other.
+
+Finding the cause for an asynchronous hang can be challenging, but it can be done with a live, hung process or with a DMP file that contains the application heap, using WinDbg. The following are the recommended steps for diagnosing the problem:
+
+1. Look at the application's UI thread to understand what scenario is blocking.
+   1. Note whether the callstack includes a `JoinableTaskFactory.WaitSynchronously` frame. If it does not, but some other synchronously blocking frame does appear, this constitutes a violation of [rule #2][ThreadingRules].
+
+      **Resolution:** Replace uses of `Task.Wait()`, `Task.Result`, `WaitHandle.WaitOne()` or other sync blocking primitives with `JoinableTask.Join()` or `JoinableTaskFactory.Run(Func<Task>)`.
+
+1. Check background threads for any that are blocked on an STA COM call that's waiting to marshal to the UI thread. If you find any, and they are performing an operation that the UI thread is blocked waiting to complete, the STA switch is probably failing.
+
+   **Resolution:** Modify the code running on the background thread to switch to the UI thread before making the call to the STA COM object, by using `await JoinableTaskFactory.SwitchToMainThreadAsync();` per [rule #1][ThreadingRules].
+
+1. Use the [`!dumpasync` WinDbg extension](dumpasync.md) to reveal the async methods that do not appear on thread callstacks to identify why an async method did not complete.
+
+## Visual Studio specific considerations
+
+If the hang shows a JoinableTaskFactory.WaitSynchronously frame near the top of the callstack on the UI thread, and if the hung application is Visual Studio itself, and if CPS was loaded before the hang, there is probably a DGML file on the disk of the repro machine that contains a hang report that shows you what went wrong. That way you may be able to avoid any WinDBG heap scouring manual investigation. Look for directories with this pattern: `%temp%\CPS.*` where `*` is a random GUID.
+   If you don't have access to the TEMP directory, you can also get the hang report from the dump file itself:
+
+        ```
+        !dumpheap -stat -type CpsJoinableTaskContext
+        !dumpheap -mt <MTAddress from previous command>
+        !do <object address from previous command>
+        !do <address from mostRecentHangReport field>
+        ```
+
+[WinDbg]: https://aka.ms/windbg-direct-download
+[ThreadingRules]: threading_rules.md

doc/dumpasync.md

@@ -0,0 +1,71 @@
+# The `!dumpasync` WinDbg extension
+
+The `!dumpasync` command is a WinDbg extension that produces a list of async method callstacks
+that may not appear on thread callstacks. This information is useful when diagnosing the cause
+for an app hang that is waiting for async methods to complete.
+
+## Tool acquisition
+
+Using this tool requires that you download and install [WinDbg][WinDbg], which can attach to a running process or DMP file. The `!dumpasync` extension is only available for WinDbg.
+
+The `!dumpasync` extension itself is exported from the `AsyncDebugTools.dll` library, which you can acquire from [our releases page](https://github.com/Microsoft/vs-threading/releases).
+
+## Usage
+
+Use WinDbg to open your DMP file or attach to your process, then execute the following commands.
+Be sure to use either the x86 or x64 version of the `AsyncDebugTools.dll` library, consistent with the version of WinDbg you are running.
+
+```windbg
+.load path\to\AsyncDebugTools.dll
+!dumpasync
+```
+
+The `!dumpasync` command will produce output such as:
+
+```
+07494c7c <0> Microsoft.Cascade.Rpc.RpcSession+<SendRequestAsync>d__49
+.07491d10 <1> Microsoft.Cascade.Agent.WorkspaceService+<JoinRemoteWorkspaceAsync>d__28
+..073c8be4 <5> Microsoft.Cascade.Agent.WorkspaceService+<JoinWorkspaceAsync>d__22
+...073b7e94 <0> Microsoft.Cascade.Rpc.RpcDispatcher`1+<>c__DisplayClass23_2+<<BuildMethodMap>b__2>d[[Microsoft.Cascade.Contracts.IWorkspaceService, Microsoft.Cascade.Common]]
+....073b60e0 <0> Microsoft.Cascade.Rpc.RpcServiceUtil+<RequestAsync>d__3
+.....073b366c <0> Microsoft.Cascade.Rpc.RpcSession+<ReceiveRequestAsync>d__42
+......073b815c <0> Microsoft.Cascade.Rpc.RpcSession+<>c__DisplayClass40_1+<<Receive>b__0>d
+
+073cdb7c <0> StreamJsonRpc.ReadBufferingStream+<FillBufferAsync>d__27
+.073cdc6c <0> StreamJsonRpc.HeaderDelimitedMessageHandler+<ReadCoreAsync>d__20
+..073cdd84 <1> StreamJsonRpc.DelimitedMessageHandler+<ReadAsync>d__22
+...073cd93c <0> Microsoft.Cascade.Rpc.Json.JsonRpcStream+<ReadAsync>d__11
+....073cd908 <0> Microsoft.Cascade.Rpc.RpcSession+<ReceiveNextMessageAsync>d__39
+
+0730c750 <0> Microsoft.Cascade.Rpc.NamedPipeServer+<RunAsync>d__23
+.0730c17c <0> Microsoft.Cascade.Rpc.PipeRpcServer+<AcceptConnectionsAsync>d__2
+..0730bff4 <0> Microsoft.Cascade.Agent.Server+<RunAsync>d__15
+...072ef4a8 <1> Microsoft.Cascade.Agent.Program+<ExecuteAsync>d__24
+
+07496420 <0> System.Threading.SemaphoreSlim+<WaitUntilCountOrTimeoutAsync>d__32
+.07496208 <0> Microsoft.Cascade.Rpc.RpcSession+<SendNextMessageAsync>d__51
+..0731c7b4 <0> Microsoft.Cascade.Rpc.RpcSession+<ProcessMessagesAsync>d__38
+...0730b6b4 <1> Microsoft.Cascade.Rpc.RpcServer+<CreateSessionAsync>d__8
+
+072fa138 <0> Microsoft.Cascade.Tracing.LogFileTraceListener+<WriteToLogAsync>d__16
+0730a138 <0> Microsoft.Cascade.Rpc.NamedPipeServer+<RunServerAsync>d__29
+```
+
+The output above is a set of stacks – not exactly callstacks, but actually "continuation stacks".
+A continuation stack is synthesized based on what code has 'awaited' the call to an async method. It's possible that the `Task` returned by an async method was awaited from multiple places (e.g. the `Task` was stored in a field, then awaited by multiple interested parties). When there are multiple awaiters, the stack can branch
+and show multiple descendents of a given frame. The stacks above are therefore actually "trees", and the leading
+dots at each frame helps recognize when trees have multiple branches.
+
+If an async method is invoked but not awaited on, the caller won't appear in the continuation stack.
+
+In the example output above, there are several stacks shown. The two frames at the bottom are two lone async method frames that have no continuations.
+In the first stack above, `SendRequestAsync` method is on top, so it is the method that contains the last `await` that didn't resume. The top frame is usually where you want to investigate the cause of an async hang. The rest of the frames in the stack give you a clue as to why this top frame matters to the rest of your application.
+​The `<0>` you see on the top frame is the state of the async state machine that tracks the async method on that frame. This state field should be interpreted based on the following table:
+
+| Value | Meaning |
+| -- | -- |
+| -2 | The async method has run to completion. This state machine is likely unrooted and subject to garbage collection. Observing this is rare because the `!dumpasync` extension filters these out as noise.
+| -1 | The async method is currently executing (you should find it on a real thread's callstack somewhere).
+| >= 0 | The 0-index into which "await" has most recently yielded. The list of awaits for the method are in strict syntax appearance order. That is, regardless of code execution, if branching, etc., it's the index into which await in code syntax order has yielded. For example, if you position the caret at the top of the method definition and search for "await ", and count how many times you hit a match, starting from 0, when you arrive at the number that you found in the state field, you've found the await that has most recently yielded. Note that when the code being debugged is compiled with certain Dev14 prerelease versions of the Roslyn compiler, this index is 1-based instead of 0-based.
+
+[WinDbg]: https://aka.ms/windbg-direct-download

doc/index.md

@@ -9,4 +9,5 @@
 
 ## Performance and responsiveness investigation techniques
 
+* [Async hang investigations](async_hang.md)
 * [Investigating Threadpool starvation issues](threadpool_starvation.md)

src/AsyncDebugTools/AsyncDebugTools.def

@@ -0,0 +1,7 @@
+EXPORTS
+     cpsnfeanalyze
+     dumpasync
+     dumpversions
+     DebugExtensionNotify
+     DebugExtensionInitialize
+     DebugExtensionUninitialize