There are many options to troubleshoot long running WCF requests. One of them is : capturing a memory dump when the long running WCF request is still executing. To capture a dump while the WCF request is still executing, you can use ServiceModelTimeTaken message inspector as shown in the previous post.

Configuring ServiceModelTimeTaken

Complete source code for ServiceModelTimeTaken is here

ServiceModelTimeTaken is a message inspector that wakes up every 60 seconds (configurable) and checks the list of running WCF requests. If any of these WCF requests are taking more than specified time, ServiceModelTimeTaken will execute the dumpCmd and captures a dump file. 

In the Web.Config or App.Config, we need to set these parameters

  1. captureDumpAfterSeconds – if the WCF request is not completed within this number of seconds, a dump will be captured
  2. dumpCmd – the debugger command to capture the dump
  3. dumpLimit – the max number of dumps to capture
  4. pollIntervalSeconds – time interval between each check for long running WCF requests

Here is the command to capture dump:

"c:\Program Files\Debugging Tools for Windows (x64)\adplus.exe" -hang -p %1 -Do -o c:\temp

Web.config or App.config

<endpointBehaviors>
  <behavior name="ServiceModelTimeTakenBehavior">
    <ServiceModelTimeTakenExtensionName captureDumpAfterSeconds="180"
                                        dumpCmd="C:\Temp\CaptureDumpCmd.bat"
                                        pollIntervalSeconds="60"
                                        dumpLimit="13" />
  </behavior>

Analyzing the dump

Open the dump file in WinDBG and load sos as shown :

0:043> .loadby sos clr

WCF Request that triggered this dump

ServiceModelTimeTaken saves this WCF request details in its threadpool object. So lets dump the threadpool object using following commands

  1. !dumpheap –stat –type – this will dump the threadpool object’s MT
  2. !dumpea –mt – this will dump the address of the threadpool object
  3. !do – this will dump the threadpool object

0:000> !dumpheap -type ServiceModelTimeTaken.ServiceModelTimeTakenThreadPool -stat
total 0 objects
Statistics:
              MT    Count    TotalSize Class Name     
000007ff00490670        1           88 ServiceModelTimeTaken.ServiceModelTimeTakenThreadPool   
   

0:000> !dumpheap -mt 000007ff00490670
         Address               MT     Size
0000000002714278 000007ff00490670       88    
total 0 objects
Statistics:
              MT    Count    TotalSize Class Name
000007ff00490670        1           88 ServiceModelTimeTaken.ServiceModelTimeTakenThreadPool
Total 1 objects
0:000> !do 0000000002714278
Name:        ServiceModelTimeTaken.ServiceModelTimeTakenThreadPool
MethodTable: 000007ff00490670
EEClass:     000007ff0046f098
Size:        88(0x58) bytes
File:        ServiceModelTimeTaken.dll
Fields:
              MT    Field   Offset                 Type VT     Attr            Value Name
000007ff003ac2c0  4000010        8 ...elTimeTakenConfig  0 instance 0000000002703108 _serviceModelTimeTakenConfig
000007ff00047658  4000011       10 ...tring, mscorlib]]  0 instance 000000000288efe8 _currentRunningRequests
000007feeaeb5ae8  4000012       18 ...reading.Semaphore  0 instance 0000000002714320 _workWaiting
000007feebbcdc30  4000013       20 ....ManualResetEvent  0 instance 0000000002714548 _pollingEvent
000007ff00490968  4000014       28 ...eModelTimeTaken]]  0 instance 00000000027142d0 _queue
000007ff00047bc0  4000015       30 ...hread, mscorlib]]  0 instance 000000000288f058 _threads
000007feebbd7be8  4000016       40         System.Int64  1 instance 634836121896815805 _dumpstartTicks
000007feebbb6728  4000017       38        System.String  0 instance 000000000275cae8 _dumpIncomingMessage
000007feebbbc610  4000018       48         System.Int32  1 instance                1 _dumpCount   

WCF Request start time

ServiceModelTimeTaken’s threadpool object has these three properties :

  1. _dumpstartTicks – execution start time of the WCF request for which this dump was taken
  2. _dumpIncomingMessage – the raw message of the above WCF request 
  3. _currentRunningRequests – list of WCF request still running at the time of this dump was taken

_dumpstartTicks saves the start time of the WCF request in ticks. To convert ticks to time, just use .formats. And to get the time of the dump use .time

So, the WCF request was started at 00:43:09 and dump was taken at 00:44:46, i.e. the request was running for more than 97 seconds


0:000> .formats 0n634836121896815805
Evaluate expression:
  Hex:     08cf6416`e03f0cbd
  Decimal: 634836121896815805
  Octal:   0043173101334017606275
  Binary:  00001000 11001111 01100100 00010110 11100000 00111111 00001100 10111101
  Chars:   ..d..?..
  Time:    Tue Sep 18 19:43:09.681 3612 (UTC - 5:00)
  Float:   low -5.50663e+019 high 1.24819e-033
  Double:  3.04228e-266
0:000> .time
Debug session time: Wed Sep 19 00:44:46.000 2012 (UTC - 5:00)
System Uptime: 1 days 17:06:49.412
Process Uptime: 0 days 0:02:11.000
  Kernel time: 0 days 0:00:01.000
  User time: 0 days 0:00:08.000

WCF Raw Message

_dumpIncomingMessage saves the raw message of the WCF request, so just do !do on it

0:043> !do 000000000275cae8
Name:        System.String
MethodTable: 000007feebbb6728
EEClass:     000007feeb73ed68
Size:        1106(0x452) bytes
File:        C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
String:      <s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/">
  <s:Header>
    <To s:mustUnderstand="1" xmlns="
http://schemas.microsoft.com/ws/2005/05/addressing/none">http://localhost:8080/IStockMarket</To>
    <Action s:mustUnderstand="1" xmlns="
http://schemas.microsoft.com/ws/2005/05/addressing/none">http://tempuri.org/IStockMarket/dumpStockValue</Action>
  </s:Header>
  <s:Body>
    <dumpStockValue xmlns="
http://tempuri.org/">
      <strSymbol>threadID-14-28-28</strSymbol>
    </dumpStockValue>
  </s:Body>
</s:Envelope>

Other WCF Requests

Now, lets dump all WCF requests that are still running (and dump their start time also).

Dump the _currentRunningRequests using sos command !do as shown :

0:043> !do 000000000288efe8
Name:        System.Collections.Generic.Dictionary`2[[System.Int64, mscorlib],[System.String, mscorlib]]
MethodTable: 000007ff00047658
EEClass:     000007feeb7dd660
Size:        88(0x58) bytes
File:        C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
Fields:
              MT    Field   Offset                 Type VT     Attr            Value Name
000007feebbbc5a0  4000c98        8       System.Int32[]  0 instance 000000000286cb08 buckets
000007feec545ec0  4000c99       10 ...non, mscorlib]][]  0 instance 00000000028a54f0 entries
000007feebbbc610  4000c9a       40         System.Int32  1 instance              124 count
000007feebbbc610  4000c9b       44         System.Int32  1 instance              633 version
000007feebbbc610  4000c9c       48         System.Int32  1 instance               99 freeList
000007feebbbc610  4000c9d       4c         System.Int32  1 instance               97 freeCount
000007feec561b98  4000c9e       18 ...Int64, mscorlib]]  0 instance 000000000288f040 comparer
000007feec5b2210  4000c9f       20 ...Canon, mscorlib]]  0 instance 0000000002724b18 keys
000007feec5abc00  4000ca0       28 ...Canon, mscorlib]]  0 instance 0000000000000000 values
000007feebbb5880  4000ca1       30        System.Object  0 instance 0000000000000000 _syncRoot
000007feebbd9f80  4000ca2       38 ...SerializationInfo  0 instance 0000000000000000 m_siInfo

_currentRunningRequests is a dictionary object, sos.dll doesn’t support dumping entries in dictionary object. So lets dump them using script.

First we need to know the number of elements in the dictionary object and the size of each element :

  1. Run !do command on the entries property to get the number of elements
  2. Run dq command on the entries property to get the size of the element. The second parameter in dq is the number of quad-word (8-bytes) to be displayed.
  3. Run ? command to get the size of the element 

0:043> !do 00000000028a54f0
Name:        System.Collections.Generic.Dictionary`2+Entry[[System.Int64, mscorlib],[System.String, mscorlib]][]
MethodTable: 000007ff00048968
EEClass:     000007ff000488a8
Size:        4752(0x1290) bytes
Array:       Rank 1, Number of elements 197, Type VALUETYPE
Element Type:System.Collections.Generic.Dictionary`2+Entry[[System.Int64, mscorlib],[System.String, mscorlib]]
Fields:
None

0:043> dq 00000000028a54f0 l40
00000000`028a54f0  000007ff`00048968 00000000`000000c5
00000000`028a5500  00000000`00000000 00000000`00000000
00000000`028a5510  00000067`ffffffff 00000000`00000000
00000000`028a5520  00000000`00000000 0000005e`ffffffff
00000000`028a5530  00000000`02a86888 08cf6417`14603bed
00000000`028a5540  ffffffff`1caf5ffa 00000000`00000000
00000000`028a5550  00000000`00000000 00000004`ffffffff
00000000`028a5560  00000000`00000000 00000000`00000000
00000000`028a5570  0000005f`ffffffff 00000000`02a58760
00000000`028a5580  08cf6417`13f210cd ffffffff`1b3d74da
00000000`028a5590  00000000`00000000 00000000`00000000
00000000`028a55a0  0000006d`ffffffff 00000000`00000000
00000000`028a55b0  00000000`00000000 00000020`ffffffff
00000000`028a55c0  00000000`00000000 00000000`00000000
00000000`028a55d0  0000006c`ffffffff 00000000`02a9f820  -> beginning of an element
00000000`028a55e0  08cf6417`1461e99d 00000023`1cae8d8a   -> end of element
00000000`028a55f0  00000000`02a9afc8 08cf6417`14619b7d   -> beginning of another element
00000000`028a5600  ffffffff`1caeff6a 00000000`0278f190   -> end of element
00000000`028a5610  08cf6416`e2f6648d ffffffff`6a39009b
00000000`028a5620  00000000`00000000 00000000`00000000
00000000`028a5630  00000026`ffffffff 00000000`0279a7b0
00000000`028a5640  08cf6416`e38efb0d ffffffff`6b419f1b
00000000`028a5650  00000000`0279ed70 08cf6416`e3db464d
00000000`028a5660  ffffffff`6b14225b 00000000`027a54c8
00000000`028a5670  08cf6416`e427b89d ffffffff`6ce8dc8b
00000000`028a5680  00000000`027a8ed0 08cf6416`e473b5bd
00000000`028a5690  ffffffff`6cbcd1ab 00000000`00000000
00000000`028a56a0  00000000`00000000 0000002e`ffffffff
00000000`028a56b0  00000000`02a9a9f8 08cf6417`1461746d
00000000`028a56c0  ffffffff`1cae107a 00000000`00000000
00000000`028a56d0  00000000`00000000 00000000`ffffffff
00000000`028a56e0  00000000`02a970c0 08cf6417`1460d82d
0:043> ? 00000000`028a55f0 - 00000000`028a55d8          -> subtract the beginning address of two elements 
Evaluate expression: 24 = 00000000`00000018

So the number of elements are 197 and size is 24. Lets use the below script to dump few elements :

.for ( r $t1 = 00000000`028a55d8; @$t2 < 7; r $t1 = @$t1 + 0x24;) {.echo **start of new WCF Request***;.formats poi(@$t1+8);!do poi(@$t1);  r $t2 = @$t2 + 1 }

Here we are starting the script from 028a55d8, we are going to dump the next 7 elements and we are going to use .formats to dump the start time of the WCF request and !do to dump the raw WCF message.

Note : we need to set the pseudo-register $t2 to zero before running the above script

  1. The green highlighted indicated start of an element
  2. The yellow highlighted is the start time of the WCF request
  3. The organ highlighted text is the raw WCF message

0:043> r $t2 = 0
0:043> .for ( r $t1 = 00000000`028a55d8; @$t2 < 7; r $t1 = @$t1 + 0x24;) {.echo **start of new WCF Request***;.formats poi(@$t1+8);!do poi(@$t1);  r $t2 = @$t2 + 1 }
**start of new WCF Request***
Evaluate expression:
  Hex:     08cf6417`1461e99d
  Decimal: 634836122771515805
  Octal:   0043173101342430364635
  Binary:  00001000 11001111 01100100 00010111 00010100 01100001 11101001 10011101
  Chars:   ..d..a..
  Time:    Tue Sep 18 19:44:37.151 3612 (UTC - 5:00)
  Float:   low 1.14057e-026 high 1.24819e-033
  Double:  3.04228e-266
Name:        System.String
MethodTable: 000007feebbb6728
EEClass:     000007feeb73ed68
Size:        1100(0x44c) bytes
File:        C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
String:      <s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/">
  <s:Header>
    <To s:mustUnderstand="1" xmlns="
http://schemas.microsoft.com/ws/2005/05/addressing/none">http://localhost:8080/IStockMarket</To>
    <Action s:mustUnderstand="1" xmlns="
http://schemas.microsoft.com/ws/2005/05/addressing/none">http://tempuri.org/IStockMarket/putStockValue</Action>
  </s:Header>
  <s:Body>
    <putStockValue xmlns="
http://tempuri.org/">
      <strSymbol>threadID-15-1-1</strSymbol>
    </putStockValue>
  </s:Body>
</s:Envelope>
   
**start of new WCF Request*** 
Invalid object
**start of new WCF Request***  
Invalid parameter poi(@$t1)
**start of new WCF Request***  
Invalid object
**start of new WCF Request***
Evaluate expression:
  Hex:     08cf6416`e427b89d
  Decimal: 634836121962395805
  Octal:   0043173101334411734235
  Binary:  00001000 11001111 01100100 00010110 11100100 00100111 10111000 10011101
  Chars:   ..d..'..
  Time:    Tue Sep 18 19:43:16.239 3612 (UTC - 5:00)
  Float:   low -1.23756e+022 high 1.24819e-033
  Double:  3.04228e-266
Name:        System.String
MethodTable: 000007feebbb6728
EEClass:     000007feeb73ed68
Size:        1110(0x456) bytes
File:        C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
String:      <s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/">
  <s:Header>
    <To s:mustUnderstand="1" xmlns="
http://schemas.microsoft.com/ws/2005/05/addressing/none">http://localhost:8080/IStockMarket</To>
    <Action s:mustUnderstand="1" xmlns="
http://schemas.microsoft.com/ws/2005/05/addressing/none">http://tempuri.org/IStockMarket/dumpStockValue</Action>
  </s:Header>
  <s:Body>
    <dumpStockValue xmlns="
http://tempuri.org/">
      <strSymbol>threadID-14-16-16</strSymbol>
    </dumpStockValue>
  </s:Body>
</s:Envelope>
 
**start of new WCF Request*** 

WCF Request’s raw message on a thread

ServiceModelTimeTaken cannot tell us on which thread these WCF requests are getting executed. So we have to go to individual threads and dump the stack objects.

To dump the WCF raw incoming message, we need to follow these steps :

  1. Run !dso – to dump the stack objects
  2. Search for Operation Context
  3. Run !do on the Operation Context
  4. Search for Request Context
  5. Run !do on the Request Context
  6. Search for Request Message
  7. Run !do on the Request Message
  8. Search for Message Data
  9. Run !do on the Message Data
  10. Search for buffer
  11. This buffer is a byte[]
  12. Use .printf to print byte array contents

0:043> !dso
OS Thread Id: 0x27b8 (43)
RSP/REG          Object           Name 
………..
000000002029E7F8 00000000026b9ce8 System.ServiceModel.ServiceHost
000000002029E800 0000000002869e48 System.ServiceModel.OperationContext
000000002029E820 00000000028d24a8 System.ServiceModel.Dispatcher.DispatchOperationRuntime 
….. 
0:043> !do 0000000002869e48
Name:        System.ServiceModel.OperationContext
MethodTable: 000007ff0049b2b8
EEClass:     000007ff004a8e50
Size:        136(0x88) bytes
File:        C:\Windows\Microsoft.Net\assembly\GAC_MSIL\System.ServiceModel\v4.0_4.0.0.0__b77a5c561934e089\System.ServiceModel.dll
Fields:
              MT    Field   Offset                 Type VT     Attr            Value Name
000007ff0049a328  4003008        8 ...ls.ServiceChannel  0 instance 00000000028ffd08 channel
000007ff002e9c68  4003009       10 ....Channels.Message  0 instance 0000000000000000 clientReply
000007feebbbd440  400300a       78       System.Boolean  1 instance                0 closeClientReply
0000000000000000  400300b       18                       0 instance 0000000000000000 extensions
000007ff0027c118  400300c       20 ...l.ServiceHostBase  0 instance 00000000026b9ce8 host
000007ff003f3df0  400300d       28 ...ls.RequestContext  0 instance 000000000280e3f0 requestContext
000007ff002e9c68  400300e       30 ....Channels.Message  0 instance 000000000280e860 request
000007ff00475db0  400300f       38 ...l.InstanceContext  0 instance 0000000002869f88 instanceContext
000007feebbbd440  4003010       79       System.Boolean  1 instance                0 isServiceReentrant
000007feebbd1d70  4003011       40 ...ncipal.IPrincipal  0 instance 0000000000000000 threadPrincipal
000007ff004eebb0  4003012       48 ...ansactionRpcFacet  0 instance 0000000000000000 txFacet
000007ff004e41a0  4003013       50 ...MessageProperties  0 instance 0000000000000000 outgoingMessageProperties
000007ff004e54b8  4003014       58 ...ls.MessageHeaders  0 instance 0000000000000000 outgoingMessageHeaders
000007ff003a5998  4003015       60 ...ls.MessageVersion  0 instance 0000000002859580 outgoingMessageVersion
000007ff003b4a50  4003016       68 ...ndpointDispatcher  0 instance 000000000270ec90 endpointDispatcher
000007feebbcde18  4003017       70  System.EventHandler  0 instance 0000000000000000 OperationCompleted
000007ff004ef160  4003007        8 ...ionContext+Holder  0 TLstatic  currentContext
    >> Thread:Value <<
0:043> !do 000000000280e3f0
Name:        System.ServiceModel.Channels.HttpRequestContext+ListenerHttpContext
MethodTable: 000007ff004e3700
EEClass:     000007ff004d6278
Size:        104(0x68) bytes
File:        C:\Windows\Microsoft.Net\assembly\GAC_MSIL\System.ServiceModel\v4.0_4.0.0.0__b77a5c561934e089\System.ServiceModel.dll
Fields:
              MT    Field   Offset                 Type VT     Attr            Value Name
000007feebbd90d8  40001a1       28      System.TimeSpan  1 instance 000000000280e418 defaultSendTimeout
000007feebbd90d8  40001a2       30      System.TimeSpan  1 instance 000000000280e420 defaultCloseTimeout
000007ff0027b750  40001a3       20         System.Int32  1 instance                2 state
000007ff002e9c68  40001a4        8 ....Channels.Message  0 instance 000000000280e860 requestMessage
000007feebbb6af0  40001a5       10     System.Exception  0 instance 0000000000000000 requestMessageException
000007feebbbd440  40001a6       24       System.Boolean  1 instance                0 replySent
000007feebbbd440  40001a7       25       System.Boolean  1 instance                0 replyInitiated
000007feebbbd440  40001a8       26       System.Boolean  1 instance                0 aborted
000007feebbb5880  40001a9       18        System.Object  0 instance 000000000280e458 thisLock
000007ff00518628  4000823       38 ...annels.HttpOutput  0 instance 0000000000000000 httpOutput
000007ff004e3d18  4000824       40 ...hannels.HttpInput  0 instance 000000000280e470 httpInput
000007ff003fd7e8  4000825       48 ...tpChannelListener  0 instance 000000000270d780 listener
000007ff004e4580  4000826       50 ...tyMessageProperty  0 instance 0000000000000000 securityProperty
000007feeaee9680  4000832       58 ...tpListenerContext  0 instance 00000000027b1370 listenerContext
0:043> !do 000000000280e860
Name:        System.ServiceModel.Channels.BufferedMessage
MethodTable: 000007ff004e6c98
EEClass:     000007ff004da290
Size:        80(0x50) bytes
File:        C:\Windows\Microsoft.Net\assembly\GAC_MSIL\System.ServiceModel\v4.0_4.0.0.0__b77a5c561934e089\System.ServiceModel.dll
Fields:
              MT    Field   Offset                 Type VT     Attr            Value Name
000007ff002e9b08  4000783       10         System.Int32  1 instance                1 state
0000000000000000  4000784        8 ...eMessageNavigator  0 instance 0000000000000000 messageNavigator
000007feebbbd440  400344a       14       System.Boolean  1 instance                0 isFault
000007feebbbd440  400344b       15       System.Boolean  1 instance                0 isEmpty
000007ff004e54b8  4003456       18 ...ls.MessageHeaders  0 instance 00000000027b1b18 headers
000007ff004e41a0  4003457       20 ...MessageProperties  0 instance 000000000280e8b0 properties
000007ff004e62f0  4003458       28 ...fferedMessageData  0 instance 000000000280e738 messageData
000007ff004e6908  4003459       30 ...ycledMessageState  0 instance 000000000280e830 recycledMessageState
000007fee5c61128  400345a       38 ...lDictionaryReader  0 instance 0000000000000000 reader
000007ff004e8e70  400345b       40 ...AttributeHolder[]  0 instance 0000000002727028 bodyAttributes
0:043> !do 000000000280e738
Name:        System.ServiceModel.Channels.TextMessageEncoderFactory+TextMessageEncoder+UTF8BufferedMessageData
MethodTable: 000007ff004e6730
EEClass:     000007ff004da0e0
Size:        104(0x68) bytes
File:        C:\Windows\Microsoft.Net\assembly\GAC_MSIL\System.ServiceModel\v4.0_4.0.0.0__b77a5c561934e089\System.ServiceModel.dll
Fields:
              MT    Field   Offset                 Type VT     Attr            Value Name
000007feec5a0608  40001c5       30 ....Byte, mscorlib]]  1 instance 000000000280e768 buffer
000007ff00492c00  40001c6        8 ...els.BufferManager  0 instance 00000000027171e0 bufferManager
000007feebbbc610  40001c7       20         System.Int32  1 instance                1 refCount
000007feebbbc610  40001c8       24         System.Int32  1 instance                0 outstandingReaders
000007feebbbd440  40001c9       28       System.Boolean  1 instance                0 multipleUsers
000007ff004e6908  40001ca       10 ...ycledMessageState  0 instance 0000000000000000 messageState
000007ff004e6ea8  40001cb       18 ...em.ServiceModel]]  0 instance 0000000002725020 messageStatePool
000007ff003fec50  400356a       40 ...extMessageEncoder  0 instance 000000000270e0b8 messageEncoder
000007ff004e7210  400356b       48 ...e.Serialization]]  0 instance 000000000280e7a0 readerPool
000007fee5c61090  400356c       50 ...ionaryReaderClose  0 instance 000000000280e7f0 onClose
000007feebbc3728  400356d       58 System.Text.Encoding  0 instance 00000000026688a8 encoding
0:043> dq 000000000280e768 l1
00000000`0280e768  00000000`0280e620   
0:043> .printf "%ma", (0280e620 + 0x10)
<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/"><s:Body><dumpStockValue xmlns="http://tempuri.org/"><strSymbol>threadID-14-28-28</strSymbol></dumpStockValue></s:Body></s:Envelope>

 

This above raw WCF message is same as the ServiceModelTimeTaken’s _dumpIncomingMessage