Add additional features to SOS DumpAsync command (#18213)
authorStephen Toub <stoub@microsoft.com>
Thu, 31 May 2018 21:09:41 +0000 (17:09 -0400)
committerGitHub <noreply@github.com>
Thu, 31 May 2018 21:09:41 +0000 (17:09 -0400)
1. Computing GC roots is a relatively slow operation, and doing it for every state machine object found in a large heap can be time consuming.  Making it opt-in with -roots command-line flag.

2. Added -waiting command-line flag.  DumpAsync will now retrieve the <>1__state field from the StateMachine, and if -waiting is specified, it'll filter down to state machines that have a state value >= 0, meaning the state machines are waiting at an await point.  For example, given this program:
```C#
using System.Threading.Tasks;
class Program
{
    static async Task Main() { await MethodA(0); await MethodA(int.MaxValue); }
    static async Task MethodA(int delay) => await MethodB(delay);
    static async Task MethodB(int delay) { await Task.Yield(); await Task.Delay(delay); }
}
```
using `!DumpAsync` outputs:
```
         Address               MT     Size Name
#0
0000026848693438 00007ff88ea35e58      120  System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Program+<MethodB>d__2, test]]
StateMachine: Program+<MethodB>d__2 (struct)
              MT    Field   Offset                 Type VT     Attr            Value Name
00007ff8e9bc4bc0  4000008        0         System.Int32  1 instance               -2 <>1__state
00007ff8e9bd82f8  4000009        8 ...TaskMethodBuilder  1 instance 0000026848693490 <>t__builder
00007ff8e9bc4bc0  400000a        4         System.Int32  1 instance                0 delay
00007ff8e9bee4d0  400000b       10 ...able+YieldAwaiter  1 instance 0000026848693498 <>u__1
00007ff8e9bcead0  400000c       18 ...vices.TaskAwaiter  1 instance 00000268486934a0 <>u__2
Continuation: 00000268486934b0 (System.Object)

#1
0000026848693e68 00007ff88ea36cc8      112  System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Program+<MethodA>d__1, test]]
StateMachine: Program+<MethodA>d__1 (struct)
              MT    Field   Offset                 Type VT     Attr            Value Name
00007ff8e9bc4bc0  4000004        0         System.Int32  1 instance               -2 <>1__state
00007ff8e9bd82f8  4000005        8 ...TaskMethodBuilder  1 instance 0000026848693ec0 <>t__builder
00007ff8e9bc4bc0  4000006        4         System.Int32  1 instance                0 delay
00007ff8e9bcead0  4000007       10 ...vices.TaskAwaiter  1 instance 0000026848693ec8 <>u__1
Continuation: 00000268486934b0 (System.Object)

#2
0000026848693ed8 00007ff88ea37188      112  System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Program+<Main>d__0, test]]
StateMachine: Program+<Main>d__0 (struct)
              MT    Field   Offset                 Type VT     Attr            Value Name
00007ff8e9bc4bc0  4000001        0         System.Int32  1 instance                1 <>1__state
00007ff8e9bd82f8  4000002        8 ...TaskMethodBuilder  1 instance 0000026848693f30 <>t__builder
00007ff8e9bcead0  4000003       10 ...vices.TaskAwaiter  1 instance 0000026848693f38 <>u__1
Continuation: 0000026848693f48 (System.Threading.Tasks.Task+SetOnInvokeMres)

#3
0000026848695d30 00007ff88ea35e58      120  System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Program+<MethodB>d__2, test]]
StateMachine: Program+<MethodB>d__2 (struct)
              MT    Field   Offset                 Type VT     Attr            Value Name
00007ff8e9bc4bc0  4000008        0         System.Int32  1 instance                1 <>1__state
00007ff8e9bd82f8  4000009        8 ...TaskMethodBuilder  1 instance 0000026848695d88 <>t__builder
00007ff8e9bc4bc0  400000a        4         System.Int32  1 instance       2147483647 delay
00007ff8e9bee4d0  400000b       10 ...able+YieldAwaiter  1 instance 0000026848695d90 <>u__1
00007ff8e9bcead0  400000c       18 ...vices.TaskAwaiter  1 instance 0000026848695d98 <>u__2
Continuation: 0000026848695dd0 (System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Program+<MethodA>d__1, test]])

#4
0000026848695dd0 00007ff88ea36cc8      112  System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Program+<MethodA>d__1, test]]
StateMachine: Program+<MethodA>d__1 (struct)
              MT    Field   Offset                 Type VT     Attr            Value Name
00007ff8e9bc4bc0  4000004        0         System.Int32  1 instance                0 <>1__state
00007ff8e9bd82f8  4000005        8 ...TaskMethodBuilder  1 instance 0000026848695e28 <>t__builder
00007ff8e9bc4bc0  4000006        4         System.Int32  1 instance       2147483647 delay
00007ff8e9bcead0  4000007       10 ...vices.TaskAwaiter  1 instance 0000026848695e30 <>u__1
Continuation: 0000026848693ed8 (System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Program+<Main>d__0, test]])

Found 5 state machines.
```
while using `!DumpAsync -waiting` outputs only:
```
         Address               MT     Size Name
#0
0000026848693ed8 00007ff88ea37188      112  System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Program+<Main>d__0, test]]
StateMachine: Program+<Main>d__0 (struct)
              MT    Field   Offset                 Type VT     Attr            Value Name
00007ff8e9bc4bc0  4000001        0         System.Int32  1 instance                1 <>1__state
00007ff8e9bd82f8  4000002        8 ...TaskMethodBuilder  1 instance 0000026848693f30 <>t__builder
00007ff8e9bcead0  4000003       10 ...vices.TaskAwaiter  1 instance 0000026848693f38 <>u__1
Continuation: 0000026848693f48 (System.Threading.Tasks.Task+SetOnInvokeMres)

#1
0000026848695d30 00007ff88ea35e58      120  System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Program+<MethodB>d__2, test]]
StateMachine: Program+<MethodB>d__2 (struct)
              MT    Field   Offset                 Type VT     Attr            Value Name
00007ff8e9bc4bc0  4000008        0         System.Int32  1 instance                1 <>1__state
00007ff8e9bd82f8  4000009        8 ...TaskMethodBuilder  1 instance 0000026848695d88 <>t__builder
00007ff8e9bc4bc0  400000a        4         System.Int32  1 instance       2147483647 delay
00007ff8e9bee4d0  400000b       10 ...able+YieldAwaiter  1 instance 0000026848695d90 <>u__1
00007ff8e9bcead0  400000c       18 ...vices.TaskAwaiter  1 instance 0000026848695d98 <>u__2
Continuation: 0000026848695dd0 (System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Program+<MethodA>d__1, test]])

#2
0000026848695dd0 00007ff88ea36cc8      112  System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Program+<MethodA>d__1, test]]
StateMachine: Program+<MethodA>d__1 (struct)
              MT    Field   Offset                 Type VT     Attr            Value Name
00007ff8e9bc4bc0  4000004        0         System.Int32  1 instance                0 <>1__state
00007ff8e9bd82f8  4000005        8 ...TaskMethodBuilder  1 instance 0000026848695e28 <>t__builder
00007ff8e9bc4bc0  4000006        4         System.Int32  1 instance       2147483647 delay
00007ff8e9bcead0  4000007       10 ...vices.TaskAwaiter  1 instance 0000026848695e30 <>u__1
Continuation: 0000026848693ed8 (System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Program+<Main>d__0, test]])

Found 3 state machines.
```
skipping the two state machines that have a `<>1__state` field value of -2 (meaning it's completed).  Note that this change has the somewhat unfortunate impact of taking a dependency on what's effectively an implementation detail of Roslyn, but the value the filtering provides is deemed to be worth it.  This design is unlikely to change in the future, and as with other diagnostic/debugging features that rely on such details, it can be updated if Roslyn ever changes its scheme.  In the meantime, the code will output a warning message if it can't find the state field.

3. If a state machine is found to have 0 roots but also to have a <>1__state value >= 0, that suggests it was dropped without having been completed, which is likely a sign of an application bug.  The command now prints out an information message to highlight that state.  For example, this program:
```C#
using System;
using System.Threading.Tasks;
class Program
{
    static void Main()
    {
        Task.Run(async () => await new TaskCompletionSource<bool>().Task);
        Console.ReadLine();
    }
}
```
when processed with `!DumpAsync -roots` results in:
```
         Address               MT     Size Name
#0
0000020787fb5b30 00007ff88ea1afe8      112  System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Boolean, System.Private.CoreLib],[Program+<>c+<<Main>b__0_0>d, test]]
StateMachine: Program+<>c+<<Main>b__0_0>d (struct)
              MT    Field   Offset                 Type VT     Attr            Value Name
00007ff8e9bc4bc0  4000003        0         System.Int32  1 instance                0 <>1__state
00007ff8e9bd0b88  4000004        8 ...Private.CoreLib]]  1 instance 0000020787fb5b88 <>t__builder
00007ff8e9bffd58  4000005       10 ...Private.CoreLib]]  1 instance 0000020787fb5b90 <>u__1
Continuation: 0000020787fb3fc8 (System.Threading.Tasks.UnwrapPromise`1[[System.Boolean, System.Private.CoreLib]])
GC roots:
Incomplete state machine (<>1__state == 0) with 0 roots.

Found 1 state machines.
```

src/ToolBox/SOS/Strike/apollososdocs.txt
src/ToolBox/SOS/Strike/sosdocs.txt
src/ToolBox/SOS/Strike/sosdocsunix.txt
src/ToolBox/SOS/Strike/strike.cpp
src/ToolBox/SOS/Strike/util.cpp
src/ToolBox/SOS/Strike/util.h

index 34e7e4d..6af5f32 100644 (file)
@@ -344,7 +344,9 @@ The arguments in detail:
 
 COMMAND: dumpasync.
 !DumpAsync [-mt <MethodTable address>] 
-           [-type <partial type name>]]
+           [-type <partial type name>]
+           [-waiting]
+           [-roots]]
 
 !DumpAsync traverses the garbage collected heap, looking for objects representing
 async state machines as created when an async method's state is transferred to the
@@ -362,7 +364,7 @@ These details include:
   
 For example:
 
-    0:011> !DumpAsync
+    0:011> !DumpAsync -roots
     #0
     000001989f413de0 00007ff88c506ba8      112  System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Program+<MethodD>d__4, test]]
     StateMachine: Program+<MethodD>d__4 (struct)
@@ -396,6 +398,8 @@ The arguments in detail:
 -mt       List only those state machine objects with the MethodTable given.
 -type     List only those state machine objects whose type name is a
           substring match of the string provided.
+-waiting  List only those state machines that are currently at an await point.
+-roots    Include GC root information for each state machine object.
 
 \\
 
index cbf7e07..93c50ff 100644 (file)
@@ -342,7 +342,9 @@ The arguments in detail:
 
 COMMAND: dumpasync.
 !DumpAsync [-mt <MethodTable address>] 
-           [-type <partial type name>]]
+           [-type <partial type name>]
+           [-waiting]
+           [-roots]]
 
 !DumpAsync traverses the garbage collected heap, looking for objects representing
 async state machines as created when an async method's state is transferred to the
@@ -360,7 +362,7 @@ These details include:
   
 For example:
 
-    0:011> !DumpAsync
+    0:011> !DumpAsync -roots
     #0
     000001989f413de0 00007ff88c506ba8      112  System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Program+<MethodD>d__4, test]]
     StateMachine: Program+<MethodD>d__4 (struct)
@@ -394,6 +396,8 @@ The arguments in detail:
 -mt       List only those state machine objects with the MethodTable given.
 -type     List only those state machine objects whose type name is a
           substring match of the string provided.
+-waiting  List only those state machines that are currently at an await point.
+-roots    Include GC root information for each state machine object.
 
 \\
 
index 574ff48..1cc92fd 100644 (file)
@@ -203,7 +203,9 @@ The arguments in detail:
 
 COMMAND: dumpasync.
 !DumpAsync [-mt <MethodTable address>] 
-           [-type <partial type name>]]
+           [-type <partial type name>]
+           [-waiting]
+           [-roots]]
 
 !DumpAsync traverses the garbage collected heap, looking for objects representing
 async state machines as created when an async method's state is transferred to the
@@ -221,7 +223,7 @@ These details include:
   
 For example:
 
-    (lldb) dumpasync
+    (lldb) dumpasync -roots
     #0
     000001989f413de0 00007ff88c506ba8      112  System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Program+<MethodD>d__4, test]]
     StateMachine: Program+<MethodD>d__4 (struct)
@@ -255,6 +257,8 @@ The arguments in detail:
 -mt       List only those state machine objects with the MethodTable given.
 -type     List only those state machine objects whose type name is a
           substring match of the string provided.
+-waiting  List only those state machines that are currently at an await point.
+-roots    Include GC root information for each state machine object.
 
 \\
 
index 6f5c161..ef19ece 100644 (file)
@@ -4123,18 +4123,20 @@ DECLARE_API(DumpAsync)
         TADDR mt = NULL;
         ArrayHolder<char> ansiType = NULL;
         ArrayHolder<WCHAR> type = NULL;
-        BOOL dml = FALSE;
+        BOOL dml = FALSE, waiting = FALSE, roots = FALSE;
         CMDOption option[] =
         {   // name, vptr, type, hasValue
             { "-mt", &mt, COHEX, TRUE },             // dump state machines only with a given MethodTable
             { "-type", &ansiType, COSTRING, TRUE },  // dump state machines only that contain the specified type substring
+            { "-waiting", &waiting, COBOOL, FALSE }, // dump state machines only when they're in a waiting state
+            { "-roots", &roots, COBOOL, FALSE },     // gather GC root information
 #ifndef FEATURE_PAL
-            { "/d", &dml, COBOOL, FALSE },          // Debugger Markup Language
+            { "/d", &dml, COBOOL, FALSE },            // Debugger Markup Language
 #endif
         };
         if (!GetCMDOption(args, option, _countof(option), NULL, 0, &nArg))
         {
-            sos::Throw<sos::Exception>("Usage: DumpAsync [-mt MethodTableAddr] [-type TypeName] [-waiting]");
+            sos::Throw<sos::Exception>("Usage: DumpAsync [-mt MethodTableAddr] [-type TypeName] [-waiting] [-roots]");
         }
         if (nArg != 0)
         {
@@ -4164,6 +4166,7 @@ DECLARE_API(DumpAsync)
         ExtOut("%" POINTERSIZE "s %" POINTERSIZE "s %8s %s\n", "Address", "MT", "Size", "Name");
 
         // Walk each heap object looking for async state machine objects.
+        BOOL missingStateFieldWarning = FALSE;
         int numStateMachines = 0;
         for (sos::ObjectIterator itr = gcheap.WalkHeap(); !IsInterrupt() && itr != NULL; ++itr)
         {
@@ -4224,6 +4227,36 @@ DECLARE_API(DumpAsync)
                 stateMachineMT = objData.MethodTable; // update from Canon to actual type
             }
 
+            // Get the current state value of the state machine. If the user has requested to filter down
+            // to only those state machines that are currently at an await, compare it against the expected
+            // waiting values.  This value can also be used in later analysis.
+            int stateValue = -2;
+            DacpFieldDescData stateField;
+            int stateFieldOffset = bStateMachineIsValueType ?
+                GetValueFieldOffset(stateMachineMT, W("<>1__state"), &stateField) :
+                GetObjFieldOffset(stateMachineAddr, stateMachineMT, W("<>1__state"), TRUE, &stateField);
+            if (stateFieldOffset < 0 || (!bStateMachineIsValueType && stateFieldOffset == 0))
+            {
+                missingStateFieldWarning = TRUE;
+                if (waiting)
+                {
+                    // waiting was specified and we couldn't find the field to satisfy the query,
+                    // so skip this object.
+                    continue;
+                }
+            }
+            else
+            {
+                MOVE(stateValue, stateMachineAddr + stateFieldOffset);
+                if (waiting && stateValue < 0)
+                {
+                    // 0+ values correspond to the await in linear sequence in the method, so a non-negative
+                    // value indicates the state machine is at an await.  Since we're filtering for waiting,
+                    // anything else should be skipped.
+                    continue;
+                }
+            }
+
             // We now have a state machine that's passed all of our criteria.  Print out its details.
 
             // Print out top level description of the state machine object.
@@ -4261,16 +4294,28 @@ DECLARE_API(DumpAsync)
 
             // Finally, output gcroots, as they can serve as call stacks, and also help to highlight
             // state machines that aren't being kept alive.
-            ExtOut("GC roots:\n");
-            IncrementIndent();
-            GCRootImpl gcroot;
-            gcroot.PrintRootsForObject(*itr, FALSE, FALSE);
-            DecrementIndent();
+            if (roots)
+            {
+                ExtOut("GC roots:\n");
+                IncrementIndent();
+                GCRootImpl gcroot;
+                int numRoots = gcroot.PrintRootsForObject(*itr, FALSE, FALSE);
+                DecrementIndent();
+
+                if (stateValue >= 0 && numRoots == 0)
+                {
+                    ExtOut("Incomplete state machine (<>1__state == %d) with 0 roots.\n", stateValue);
+                }
+            }
 
             ExtOut("\n");
         }
 
         ExtOut("\nFound %d state machines.\n", numStateMachines);
+        if (missingStateFieldWarning)
+        {
+            ExtOut("Warning: Could not find a state machine's <>1__state field.\n");
+        }
         return S_OK;
     }
     catch (const sos::Exception &e)
index c7d78d2..ba2626f 100644 (file)
@@ -1838,6 +1838,66 @@ int GetObjFieldOffset(CLRDATA_ADDRESS cdaObj, CLRDATA_ADDRESS cdaMT, __in_z LPCW
 #undef EXITPOINT    
 }
 
+
+// Return value: -1 = error
+//               -2 = not found
+//             >= 0 = offset to field from cdaValue
+int GetValueFieldOffset(CLRDATA_ADDRESS cdaMT, __in_z LPCWSTR wszFieldName, DacpFieldDescData* pDacpFieldDescData)
+{
+#define EXITPOINT(EXPR) do { if(!(EXPR)) { return -1; } } while (0)
+
+    const int NOT_FOUND = -2;
+    DacpMethodTableData dmtd;
+    DacpMethodTableFieldData vMethodTableFields;
+    DacpFieldDescData vFieldDesc;
+    DacpModuleData module;
+    static DWORD numInstanceFields = 0; // Static due to recursion visiting parents
+    numInstanceFields = 0;
+
+    EXITPOINT(vMethodTableFields.Request(g_sos, cdaMT) == S_OK);
+
+    EXITPOINT(dmtd.Request(g_sos, cdaMT) == S_OK);
+    EXITPOINT(module.Request(g_sos, dmtd.Module) == S_OK);
+    if (dmtd.ParentMethodTable)
+    {
+        DWORD retVal = GetValueFieldOffset(dmtd.ParentMethodTable, wszFieldName, pDacpFieldDescData);
+        if (retVal != NOT_FOUND)
+        {
+            // Return in case of error or success. Fall through for field-not-found.
+            return retVal;
+        }
+    }
+
+    CLRDATA_ADDRESS dwAddr = vMethodTableFields.FirstField;
+    ToRelease<IMetaDataImport> pImport = MDImportForModule(&module);
+
+    while (numInstanceFields < vMethodTableFields.wNumInstanceFields)
+    {
+        EXITPOINT(vFieldDesc.Request(g_sos, dwAddr) == S_OK);
+
+        if (!vFieldDesc.bIsStatic)
+        {
+            NameForToken_s(TokenFromRid(vFieldDesc.mb, mdtFieldDef), pImport, g_mdName, mdNameLen, false);
+            if (_wcscmp(wszFieldName, g_mdName) == 0)
+            {
+                if (pDacpFieldDescData != NULL)
+                {
+                    *pDacpFieldDescData = vFieldDesc;
+                }
+                return vFieldDesc.dwOffset;
+            }
+            numInstanceFields++;
+        }
+
+        dwAddr = vFieldDesc.NextField;
+    }
+
+    // Field name not found...
+    return NOT_FOUND;
+
+#undef EXITPOINT    
+}
+
 // Returns an AppDomain address if AssemblyPtr is loaded into that domain only. Otherwise
 // returns NULL
 CLRDATA_ADDRESS IsInOneDomainOnly(CLRDATA_ADDRESS AssemblyPtr)
index fa26c3f..7851654 100644 (file)
@@ -1388,6 +1388,7 @@ void DisplayFields (CLRDATA_ADDRESS cdaMT, DacpMethodTableData *pMTD, DacpMethod
                     DWORD_PTR dwStartAddr = 0, BOOL bFirst=TRUE, BOOL bValueClass=FALSE);
 int GetObjFieldOffset(CLRDATA_ADDRESS cdaObj, __in_z LPCWSTR wszFieldName, BOOL bFirst=TRUE);
 int GetObjFieldOffset(CLRDATA_ADDRESS cdaObj, CLRDATA_ADDRESS cdaMT, __in_z LPCWSTR wszFieldName, BOOL bFirst=TRUE, DacpFieldDescData* pDacpFieldDescData=NULL);
+int GetValueFieldOffset(CLRDATA_ADDRESS cdaMT, __in_z LPCWSTR wszFieldName, DacpFieldDescData* pDacpFieldDescData);
 
 BOOL IsValidToken(DWORD_PTR ModuleAddr, mdTypeDef mb);
 void NameForToken_s(DacpModuleData *pModule, mdTypeDef mb, __out_ecount (capacity_mdName) WCHAR *mdName, size_t capacity_mdName,