IIS Support Blog

11 MIN READ

Capturing Memory Dumps on Long Running WCF Requests

Microsoft

Nov 16, 2018

First published on MSDN on Sep 19, 2012

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

captureDumpAfterSeconds – if the WCF request is not completed within this number of seconds, a dump will be captured
dumpCmd – the debugger command to capture the dump
dumpLimit – the max number of dumps to capture
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

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

!dumpheap –stat –type – this will dump the threadpool object’s MT

!dumpea –mt – this will dump the address of the threadpool object

!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 :

_dumpstartTicks – execution start time of the WCF request for which this dump was taken

_dumpIncomingMessage – the raw message of the above WCF request

_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 :

Run !do command on the entries property to get the number of elements

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.

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

The green highlighted indicated start of an element

The yellow highlighted is the start time of the WCF request

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 :

Run !dso – to dump the stack objects

Search for Operation Context

Run !do on the Operation Context

Search for Request Context

Run !do on the Request Context

Search for Request Message

Run !do on the Request Message

Search for Message Data

Run !do on the Message Data

Search for buffer

This buffer is a byte[]

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>