August 2010 - Posts
I got an email from a former client a couple of days ago with roughly the following problem description:
I’m trying to run a unit test (with MSTest) which calls an interop function. The native DLL (written in C) is located in C:\Windows\System32. For some reason, when running the test Visual Studio can’t seem to find the DLL, and throws a FileNotFoundException.
Moreover, I can’t even see the DLL in the File—>Open dialog in Visual Studio! I tried launching Visual Studio as admin and as standard user but the result was the same. What am I missing here?
This was a good opportunity to demonstrate psychic debugging skills. Here’s what I wrote back:
The test probably runs as 32-bit and therefore it looks under C:\Windows\SysWOW64.
Indeed, VSTestHost.exe (the external executable that runs Visual Studio 2008 tests) is compiled with the /32BIT+ CLR header flag, forcing it to run as a 32-bit process even on 64-bit Windows. There are some instructions elsewhere that remove the 32-bit flag from the VSTestHost.exe file, in an obviously unsupported fashion. Finally, Visual Studio 2010 seems to offer a way to run unit tests in a 64-bit process.
Since Visual Studio is a 32-bit process, it is also not a big surprise that the File—>Open dialog “doesn’t work” by not showing the file. Here’s a simple experiment you can perform on your 64-bit Windows:
- Run two copies of Notepad: C:\Windows\System32\notepad.exe and C:\Windows\SysWOW64\notepad.exe
- Open an administrative command prompt and copy some text file to C:\Windows\System32
- Now try opening the file in both Notepad instances using the File—>Open dialog
Bonus reading: More than two years I resolved a similar problem over the phone.
More bonus reading: User-account control redirection can cause similar inconsistencies. A 32-bit application without a manifest that runs without administrative privileges will write a text file to C:\Program Files successfully, but upon closer examination with Windows Explorer you won’t find the file there. Instead, it will be in a redirected VirtualStore folder under %LOCALAPPDATA%. See this great post for more resources, labs, and presentations.
Starting from CLR 4.0, multiple versions of the CLR can be loaded into the same process. This doesn’t mean that you can mix the 1.1 and 2.0 runtimes, but you can have CLR 2.0 loaded in the same process with CLR 4.0. This is great news for managed shell extension developers, managed COM object developers, and other library developers whose libraries are consumed by unmanaged code.
The CLR Inside Out: In-Process Side-by-Side column contains all the nitty-gritty details. One fact you should be aware of is that if you load a managed library that targets CLR 2.0 from a managed app that targets CLR 4.0, the managed library will use the 4.0 runtime.
Anyway, the point of this post is to show you a quick demo of having two CLR versions loaded into the same process. One way to do this is using the new CLR hosting interfaces that give you the ability to load two versions of the CLR. But that’s cheating.
Instead, I wrote two managed COM libraries. One of them targets CLR 2.0 and the other targets CLR 4.0. Next, I wrote a simple C++ application that loads both COM objects. Here’s the result of the lm command in WinDbg:
0:009> lm vm clr
start end module name
63240000 638af000 clr (deferred)
Image path: C:\Windows\Microsoft.NET\Framework\v4.0.30319\clr.dll
Image name: clr.dll
Timestamp: Thu Mar 18 09:44:47 2010 (4BA1D9EF)
CheckSum: 00671FC0
ImageSize: 0066F000
File version: 4.0.30319.1
Product version: 4.0.30319.1
File flags: 8 (Mask 3F) Private
File OS: 4 Unknown Win32
File type: 2.0 Dll
File date: 00000000.00000000
Translations: 0409.04b0
CompanyName: Microsoft Corporation
ProductName: Microsoft® .NET Framework
InternalName: clr.dll
OriginalFilename: clr.dll
ProductVersion: 4.0.30319.1
FileVersion: 4.0.30319.1 (RTMRel.030319-0100)
PrivateBuild: DDBLD766
FileDescription: Microsoft .NET Runtime Common Language Runtime - WorkStation
LegalCopyright: © Microsoft Corporation. All rights reserved.
Comments: Flavor=Retail
0:009> lm vm mscorwks
start end module name
72890000 72e21000 mscorwks (deferred)
Image path: C:\Windows\Microsoft.NET\Framework\v2.0.50727\mscorwks.dll
Image name: mscorwks.dll
Timestamp: Thu May 13 13:29:46 2010 (4BEBD49A)
CheckSum: 0059AAE3
ImageSize: 00591000
File version: 2.0.50727.4952
Product version: 2.0.50727.4952
File flags: 0 (Mask 3F)
File OS: 4 Unknown Win32
File type: 2.0 Dll
File date: 00000000.00000000
Translations: 0409.04b0
CompanyName: Microsoft Corporation
ProductName: Microsoft® .NET Framework
InternalName: mscorwks.dll
OriginalFilename: mscorwks.dll
ProductVersion: 2.0.50727.4952
FileVersion: 2.0.50727.4952 (win7RTMGDR.050727-4900)
FileDescription: Microsoft .NET Runtime Common Language Runtime - WorkStation
LegalCopyright: © Microsoft Corporation. All rights reserved.
Comments: Flavor=Retail
And here’s the output from the managed COM objects—all they do is output the CLR version using Environment.Version:
Hello World from .NET 2.0
.NET version: 2.0.50727.4952
Hello World from .NET 4.0
.NET version: 4.0.30319.1
You can download the Visual Studio 2010 solution with the three projects I described above:
In our previous trip to PSSCor2-land, we’ve seen some object inspection commands tailored for ADO.NET and ASP.NET applications. This time, let’s take a step back and use some commands that display and analyze the managed heap.
The fundamental !DumpHeap command receives a minor facelift in PSSCor2—it has some new parameters. One welcome addition is the –gen parameter, which filters the output by a certain GC generation. Another great idea is the –random switch that prints every 1000th object so that your screen doesn’t get flooded with instances and so that you can inspect a random sampling. Finally, there’s also the –l switch, which limits the output to a certain number of objects from each GC heap.
For example, here are the LOH objects on my heap (note that the output includes natural LOH fragmentation):
0:006> !dumpheap -stat -gen 3
Loading the heap objects into our cache.
total 53,999 objects
Statistics:
MT Count TotalSize Class Name
0x00832328 44 704 Free
0x001a84f0 43 84,760 System.Object[]
Total 87 objects, Total size: 85,464
Another neat command is called !GCRef. Despite the similarity to !gcroot, this command shows you both references to the object (parents) and references from the object (children), even if the object is no longer rooted. Note that this command performs a complete heapwalk, so it might take a significant amount of time to complete.
For example, here is the list of an employee’s managers (assuming that the Employee class representing a manager has a reference to their direct reports):
0:003> .foreach (mgr {!gcref -shortparent 02500b38}) {!dumpfield -field _name -string mgr}
David
Kate
Next, the neat !CLRUsage command displays the commit and reserve sizes of the GC heaps, similarly to !eeheap –gc. Here are the two outputs side-by-side—you’d probably agree that the former is more readable:
0:003> !CLRUsage -v
Native Heap for .NET: 0x00470000
Number of GC Heaps: 1
seg base start end commit reserved
02470000 02471000 02471024 000c2000 00f3e000
seg base start end commit reserved
03470000 03471000 034764a0 00012000 00fee000
Total Size 0xbc494(771,220)
------------------------------
GC Heap Size 0xbc494(771,220)
Total Commit Size 000d4000 (0 MB)
Total Reserved Size 01f2c000 (31 MB)
Initial reservation type:
Initial Allocation Size: 0 (0) (0 MB)
Reserved Memory Size: 2000000 (33,554,432) (32 MB)
Reserved Memory Limit Size: 2000000 (33,554,432) (32 MB)
0:003> !eeheap -gc
Number of GC Heaps: 1
generation 0 starts at 0x02471018
generation 1 starts at 0x0247100c
generation 2 starts at 0x02471000
ephemeral segment allocation context: none
segment begin allocated size reserved
02470000 02471000 02527ff4 0x000b6ff4(749,556) 00f3e000
Large object heap starts at 0x03471000
segment begin allocated size reserved
03470000 03471000 034764a0 0x000054a0(21,664) 00fee000
Total Size 0xbc494(771,220)
------------------------------
GC Heap Size 0xbc494(771,220)
Finally, I covered additional GC-related commands in PSSCor2 in a surprisingly old set of posts about the Silverlight SOS (!ListNearObj, !GCWhere, and !HeapStat). The same commands are now part of the CLR 4.0 SOS, but if you want to use them with a CLR 2.0 process, PSSCor2 gives you just that.
The .NET GC determines which objects are reachable by constructing a graph of references, starting from a set of roots. One type of roots is local references that are stored on thread stacks. The GC relies on the JIT to supply it with information about the local variables in each active method, and uses that information to determine whether a root should be traversed.
When all optimizations are enabled, the JIT and GC cooperate so that local roots are relevant only as long as the local variable is still going to be used. This is a source of strange bugs—two of them are the Timer bug and the finalization race condition.
Why am I telling you all this? Well, it turns out there’s a cool SOS command called !GCInfo that can give you information on local root relevance within a method. In other words, it can tell you when (in terms of instructions) a local variable ceases to be an active local root.
For the sake of simplicity, let’s consider Debug builds only and the following method:
static void Main(string[] args)
{
string s = "Hello World";
Console.ReadLine();
}
Because of the Debug build, the local variable s is not going to be optimized away. Furthermore, its lifetime should extend until the end of the method, and not just the first line. Let’s verify this:
0:000> !CLRStack
OS Thread Id: 0x1f04 (0)
ESP EIP
[…edited for brevity…]
003ced00 704c9fbb System.IO.StreamReader.ReadBuffer()
003ced14 704c9e0c System.IO.StreamReader.ReadLine()
003ced34 70a5dd3d System.IO.TextReader+SyncTextReader.ReadLine()
003ced40 709a31c7 System.Console.ReadLine()
003ced48 005c009b FreakishTimerBug.Program.Main()
0:000> !gcinfo 005c009b
entry point 005c0070
Normal JIT generated code
GC info 001b17e0
Method info block:
method size = 0031
prolog size = 9
epilog size = 4
epilog count = 1
epilog end = yes
callee-saved regs = EBP
ebp frame = yes
fully interruptible= yes
double align = no
arguments size = 0 DWORDs
stack frame size = 2 DWORDs
untracked count = 1
var ptr tab count = 1
epilog at 002D
argTabOffset = 4
31 D2 B8 9A 40 |
01 04 |
Pointer table:
04 | [EBP-04H] an untracked local
08 1C 15 | 001C..0031 [EBP-08H] a pointer
F3 43 | 0023 reg EAX becoming live
F0 00 | 002B reg EAX becoming dead
FF |
0:000> !u 005c009b
Normal JIT generated code
FreakishTimerBug.Program.Main(System.String[])
Begin 005c0070, size 31
[…edited for brevity…]
005c0070 push ebp
005c0071 mov ebp,esp
005c0073 sub esp,8
005c0076 mov dword ptr [ebp-4],ecx
005c0079 cmp dword ptr ds:[1B30E4h],0
005c0080 je 005c0087
005c0082 call mscorwks!JIT_DbgIsJustMyCode (710cb329)
005c0087 xor edx,edx
005c0089 mov dword ptr [ebp-8],edx
005c008c nop
005c008d mov eax,dword ptr ds:[3222030h] ("Hello World")
005c0093 mov dword ptr [ebp-8],eax
005c0096 call mscorlib_ni+0x6d31b8 (709a31b8) (System.Console.ReadLine(), mdToken: 060007bb)
>>> 005c009b nop
005c009c nop
005c009d mov esp,ebp
005c009f pop ebp
005c00a0 ret
The local variable s is stored on the stack, in EBP-8. It becomes relevant at offset 1C from the beginning of the method, which is the NOP instruction at 005c008C, and it remains relevant throughout the entire method.
If we modify the code slightly, we might expect a different outcome:
static void Main(string[] args)
{
string s = "Hello World";
s = null;
Console.ReadLine();
}
In this version, the local variable is explicitly cleared before the Console.ReadLine call, so it might have an effect on the JIT’s table:
0:000> !gcinfo 004000a0
entry point 00400070
Normal JIT generated code
GC info 001917e0
Method info block:
method size = 0036
prolog size = 9
epilog size = 4
epilog count = 1
epilog end = yes
callee-saved regs = EBP
ebp frame = yes
fully interruptible= yes
double align = no
arguments size = 0 DWORDs
stack frame size = 2 DWORDs
untracked count = 1
var ptr tab count = 1
epilog at 0032
argTabOffset = 4
36 D2 B8 9A 40 |
01 04 |
Pointer table:
04 | [EBP-04H] an untracked local
08 1C 1A | 001C..0036 [EBP-08H] a pointer
F3 43 | 0023 reg EAX becoming live
F0 05 | 0030 reg EAX becoming dead
FF |
0:000> !u 004000a0
Normal JIT generated code
FreakishTimerBug.Program.Main(System.String[])
Begin 00400070, size 36
[…edited for brevity…]
00400070 push ebp
00400071 mov ebp,esp
00400073 sub esp,8
00400076 mov dword ptr [ebp-4],ecx
00400079 cmp dword ptr ds:[1930E4h],0
00400080 je 00400087
00400082 call mscorwks!JIT_DbgIsJustMyCode (710cb329)
00400087 xor edx,edx
00400089 mov dword ptr [ebp-8],edx
0040008c nop
0040008d mov eax,dword ptr ds:[35E2030h] ("Hello World")
00400093 mov dword ptr [ebp-8],eax
00400096 xor edx,edx
00400098 mov dword ptr [ebp-8],edx
0040009b call mscorlib_ni+0x6d31b8 (709a31b8) (System.Console.ReadLine(), mdToken: 060007bb)
>>> 004000a0 nop
004000a1 nop
004000a2 mov esp,ebp
004000a4 pop ebp
004000a5 ret
There’s no change—the EBP-8 local variable remains active throughout the end of the method. You can even see the instructions that assign 0 to it—at 00400096 and 00400098, but it doesn’t change the relevance lifetime of the local variable. And it makes sense to some extent—the local variable’s eligibility to be considered a local root isn’t affected by whether the code stores a null in it.
This whole discussion, of course, is irrelevant in the Release build. In fact, the local variable wouldn’t even be there. In order to have something to show you, I modified the code slightly:
static void Main(string[] args)
{
int k = int.Parse(Console.ReadLine());
float j = float.Parse(Console.ReadLine());
string s = Console.ReadLine();
Console.WriteLine(s + j + k);
}
…and then compiled it in the Release build, and:
0:000> !gcinfo 002c0085
entry point 002c0070
Normal JIT generated code
GC info 001e17fc
Method info block:
[…edited for brevity…]
Pointer table:
14 5D 27 | 005D..0084 [EBP-14H] a pointer
9C 40 | 001C call [ ESI ] argMask=00
A2 40 | 003E call [ ESI ] argMask=00
B5 40 | 0073 call [ ESI ] argMask=00
9D 40 | 0090 call [ ESI ] argMask=00
FF |
0:000> !u 002c0085
Normal JIT generated code
FreakishTimerBug.Program.Main(System.String[])
Begin 002c0070, size a4
[…edited for brevity…]
002c00be call mscorlib_ni+0x6d1e38 (709a1e38) (System.Console.get_In(), mdToken: 06000772)
002c00c3 mov ecx,eax
002c00c5 mov eax,dword ptr [ecx]
002c00c7 call dword ptr [eax+64h]
002c00ca mov dword ptr [ebp-14h],eax
002c00cd mov ecx,offset mscorlib_ni+0x26a32c (7053a32c) (MT: System.Single)
002c00d2 call 001d201c (JitHelp: CORINFO_HELP_NEWSFAST)
002c00d7 mov esi,eax
002c00d9 mov ecx,offset mscorlib_ni+0x272d34 (70542d34) (MT: System.Int32)
002c00de call 001d201c (JitHelp: CORINFO_HELP_NEWSFAST)
002c00e3 mov edi,eax
002c00e5 fld dword ptr [ebp-10h]
002c00e8 fstp dword ptr [esi+4]
002c00eb mov edx,esi
002c00ed mov dword ptr [edi+4],ebx
002c00f0 push edi
002c00f1 mov ecx,dword ptr [ebp-14h]
002c00f4 call mscorlib_ni+0x20cc70 (704dcc70) (System.String.Concat(System.Object, System.Object, System.Object), mdToken: 060001c7)
002c00f9 mov esi,eax
002c00fb call mscorlib_ni+0x22d380 (704fd380) (System.Console.get_Out(), mdToken: 06000773)
[…edited for brevity…]
Indeed, in the new method, the s variable is stored on the stack, and it becomes alive at 002C00C, immediately after the return value (from EAX) of Console.ReadLine is assigned to it. It remains alive all the way through 002C00F4, where it stored in ECX and passed to String.Concat.
This is just a quick post to let you know about two important accomplishments we at Sela had in the past few days.
In a few days, the WCF 4.0 MOC 10263A (Microsoft Official Course) is going to be released to training centers all over the world. This course was developed by Sela from scratch, and I’ve been a fly on the wall during its production process. (Well, to tell you the truth, I did quite a bit of technical editing work on this project, which has certainly earned me some hate from the content producers :-))
Taking part in this project was really an incredible experience. The level of attention to detail required, the technical depth, the vast amount of labs and code samples, the gigantic, 1,300-page student handbook full of reference material—made the development of this course much more complex but also much more satisfying.
This course’s eight modules cover most of the ground for novice WCF developers, but also provides a great deal of technical material for more experienced WCF programmers. Ido has already delivered a Beta cycle of this course, and the feedback has been excellent. It’s a great pride to know that our materials will be used to teach a large number of people the official way of using WCF.
Additional information:
The second big thing we have going on right now is a set of Windows Phone 7 labs, demos, samples, and articles for the XNA Creators Club. There’s a large team at Sela led by Alex Golesh working on incredibly interesting educational material that shows you how to write XNA games for Windows Phone 7.
Some of the stuff you can already find online includes articles on gestures and 2D assets, sound, music and orientation samples, and an awesome game development labs. (This is a great opportunity to remind you that if you haven’t got a chance to play around with the Windows Phone 7 Developer Tools yet, you should certainly do so!)
This project is not done yet—there’s still lots of work ahead, so stay tuned for more labs, articles, and samples. As Windows Phone 7 is nearing its announced release date, there will be a great amount of content produced by Sela that you can leverage to start writing your next application for the new platform.
Additional information:
In the previous installment, we’ve seen how PSSCor2 makes it easy to display the contents of a DateTime, of an IPAddress, of an XmlDocument, and of certain collection classes. Now we’ll take a look at some additional commands that inspect heap objects.
The !DumpField commands automates the process of displaying a particular object field (by field name). This is especially useful when combined with some looping constructs like .foreach to execute a script in the debugger session. In the following example, I have an Employee class that has an _id field, and I want to display all the IDs of all the employees currently present on the managed heap:
0:000> .foreach (emp {!dumpheap -type SimpleManagedApp.Employee -short}) {!DumpField -field _id emp}
2775
1771
2309
1170
2636
1819
Next, there are two specialized commands for analyzing DataTables: !DumpDataTables and !DumpColumnNames. The first is extremely useful when you want to see if there are any large DataTables consuming a significant amount of memory; the latter is useful for inspecting these specific tables and detecting what they are. For example:
0:003> !dumpdatatables
Loading the heap objects into our cache.
DataTable Rows Columns DataSet nextRowID ColumnCount
-----------------------------------------------------------------------------------------------
0x25fd6a0 0x25fda78 0x25fd928 0x25e145c 3 0
Total 1 DataTable objects
0:003> !dumpdatatables -size
*** Runs !ObjSize on each DataTable so this may take a while!
Loading the heap objects into our cache.
sizeof(025fd6a0) = 7,040 ( 0x1b80) bytes (System.Data.DataTable)
DataTable TotalSize Rows Columns DataSet nextRowID ColumnCount
-----------------------------------------------------------------------------------------------
0x25fd6a0 7,040 0x25fda78 0x25fd928 0x25e145c 3 0
Total 1 DataTable objects
0:003> !dumpcolumnnames 0x25fd6a0
Column Names for DataTable: 0x25fd6a0
author, book_Text
(This DataTable was created by loading a simple XML document into a DataSet.)
Similarly, there are numerous commands for inspecting the state of an ASP.NET application. Here’s some example output—I’m sure you’ll figure out these commands from context, and using the !help command:
0:018> !aspxpages
Going to dump the HttpContexts found in the heap.
Loading the heap objects into our cache.
HttpContext Timeout Completed Running ThreadId ReturnCode Verb RequestPath+QueryString
0x04f7715c 19200 Sec yes XXX 200 GET /Default.aspx
0x050fc398 110 Sec yes XXX 404 GET /favicon.ico
0x0514aaac 19200 Sec no 85 Sec 6 200 POST /Default.aspx
Total 3 HttpContext objects
0:018> !DumpASPNETCache -s
Going to dump the ASP.NET Cache.
Loading the heap objects into our cache.
Address MT Priority Create Time Expires Last Updated Key Class Name
051502a4 001a9148 Normal 08/23/2010 12:06:39 12/31/9999 23:59:59 0 MyKey System.String
050fda8c 0a951300 Normal 08/23/2010 12:06:39 12/31/9999 23:59:59 0 dmachine/webroot/1/favicon.ico System.Web.CachedPathData
050e1a94 0f8caeec Normal 08/23/2010 12:06:38 08/23/2010 12:07:39 08/23/2010 12:06:39 e1Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.1; WOW64; Triden System.Web.Mobile.MobileCapabilities
050e1a94 0f8caeec Normal 08/23/2010 12:06:38 12/31/9999 23:59:59 0 z-90014800 System.Web.Mobile.MobileCapabilities
050b3d4c 0f8c6bd0 Normal 08/23/2010 12:06:38 12/31/9999 23:59:59 08/23/2010 12:06:39 cdefault.aspx.cdcab7d2 System.Web.Compilation.BuildResultCompiledTemplateType
050af710 0044c774 Normal 08/23/2010 12:06:38 12/31/9999 23:59:59 08/23/2010 12:06:38 yapp_web_mrdimh5w System.Reflection.Assembly
04f95fb0 0ec031d4 Normal 08/23/2010 12:06:37 12/31/9999 23:59:59 08/23/2010 12:06:39 hc:\users\sasha\documents\visual studio 2010\Projects\SimpleManagedApp\MyWebApp\Default.aspx System.Web.Security.FileSecurityDescriptorWrapper
04f8fde0 0a951300 Normal 08/23/2010 12:06:37 12/31/9999 23:59:59 08/23/2010 12:06:39 dmachine/webroot/1/default.aspx System.Web.CachedPathData
04f50e84 0a951300 Normal 08/23/2010 12:06:36 12/31/9999 23:59:59 08/23/2010 12:06:39 dmachine/webroot/1 System.Web.CachedPathData
04f46184 0a951300 Normal 08/23/2010 12:06:36 12/31/9999 23:59:59 08/23/2010 12:06:39 dmachine/webroot System.Web.CachedPathData
04f38a10 0a951300 Normal 08/23/2010 12:06:36 12/31/9999 23:59:59 08/23/2010 12:06:39 dmachine System.Web.CachedPathData
Total 11 cache objects, Total size: 792
0:018> !DumpHttpRuntime -r
Going to dump the HttpRuntimes found in the heap.
Loading the heap objects into our cache.
HttpRuntime 0x04f2c9d8:
_shutdownInProgress: 0
_requestQueue:
RequestQueue 0x04f777c4:
_minExternFreeThreads: 704
_minLocalFreeThreads: 608
_appDomainAppPath: c:\users\sasha\documents\visual studio 2010\Projects\SimpleManagedApp\MyWebApp\
_appDomainAppId: f46e0782
_fcm:
Name: System.Web.FileChangesMonitor
MethodTable: 0a6dd350
EEClass: 0a76d8b0
Size: 60(0x3c) bytes
GC Generation: 1
Fields: […removed for brevity…]
_cacheInternal:
Name: System.Web.FileChangesMonitor
MethodTable: 0a6dd350
EEClass: 0a76d8b0
Size: 60(0x3c) bytes
GC Generation: 1
Fields: […removed for brevity…]
_isOnUNCShare: 0
_debuggingEnabled: 1
-----------------
Total 1 HttpRuntime objects
Additional commands in this category that you might find useful are !DumpRequestQueues, !DumpRequestTable, !DumpHistoryTable, !DumpBuckets, and !GetWorkItems. Some of them require rather delicate understanding of IIS internals.
Next time: Miscellaneous GC-heap-related commands.
PSSCor2 is a recently released debugging extension used internally by Microsoft support engineers to debug managed applications. It’s a separate download that installs its 32-bit and 64-bit flavors, and currently there’s only a version that works with CLR 2.0, but its additions on top of the core SOS are significant and therefore it’s worth learning how to use them.
In this installment, we’ll take a look at some of the new object inspection commands. Stay tuned for more—all in all, there are a couple of dozen new commands that I’d like to show you.
Let’s start with some object inspection commands. Although SOS ships with the very useful !do and !dumpvc commands, it’s somewhat difficult to parse some primitive types nevertheless. For example, if you have a DateTime instance, inspecting it with !dumpvc provides the following (not very helpful) output:
0:000> !do 024c90a8
Name: SimpleManagedApp.Program
MethodTable: 002e32e4
EEClass: 002e1350
Size: 16(0x10) bytes
GC Generation: 0
Fields:
[…edited for brevity…]
MT Type VT Attr Value Name
70518148 System.DateTime instance 024c90ac date
0:000> !dumpvc 70518148 024c90ac
Name: System.DateTime
MethodTable 70518148
EEClass: 702f0564
Size: 16(0x10) bytes
Fields:
MT Type VT Attr Value Name
705193ec System.UInt64 instance 9857553727207558089 dateData
On the other hand, using the new !PrintDateTime command, this is a piece of cake:
0:000> !PrintDateTime 024c90ac
2888cbc9
As a TimeSpan: 11409205.16:52:00.7558089
As a DateTime: 08/23/2010 14:03:55
Note that there are two additional new commands, !ConvertVTDateToDate and !ConvertTicksToDate, which accomplish essentially the same thing. To the former you pass a DateTime instance; to the latter, you pass the dateData field—the number of ticks embedded in the DateTime instance. Using the information from the previous example:
0:000> !ConvertTicksToDate 9857553727207558089
2888cbc9
As a TimeSpan: 11409205.16:52:00.7558089
As a DateTime: 08/23/2010 14:03:55
Similarly, the new !PrintIPAddress command displays the contents of an IPAddress instance (a fairly ugly parsing task without it):
0:000> !dumpvc 6e52e13c 025d90ec
Name: System.Net.IPAddress
MethodTable 6e52e13c
EEClass: 6e39f9d8
Size: 40(0x28) bytes
Fields:
MT Type VT Attr Value Name
70542374 System.Int64 1 instance 72058141349699900 m_Address
70540ae8 System.String 0 instance 00000000 m_ToString
6e52dca0 System.Int32 1 instance 39686420 m_Family
70534268 System.UInt16[] 0 instance 00000000 m_Numbers
70542374 System.Int64 1 instance 0 m_ScopeId
70542d34 System.Int32 1 instance 2 m_HashCode
[…edited for brevity…]
0:000> !PrintIPAddress 025d90ec
127.0.0.1
Another unpleasant thing that you had to accomplish manually using SOS is displaying the contents of an XML document. This isn’t trivial, as the string representation of the XML is not part of the XmlDocument instance. Fortunately, the new !DumpXmlDocument command prints out the document for you:
0:000> !dso
OS Thread Id: 0x5a8 (0)
ESP/REG Object Name
[…edited for brevity…]
003ceea4 025295c0 System.Xml.XmlDocument
003cf154 02529098 System.Object[] (System.String[])
0:000> !do 025295c0
Name: System.Xml.XmlDocument
MethodTable: 6c527e14
EEClass: 6c476744
Size: 156(0x9c) bytes
GC Generation: 0
Fields:
[…huge dump of all XmlDocument fields…]
0:000> !DumpXmlDocument 025295c0
<books>
<book author="Tolstoy">
War and Peace
</book>
</books>
Nice! Let’s conclude today’s PSSCor2 tour with a command that has lots of potential—!DumpCollection. This command takes a collection and displays in a convenient way the elements of the collection, eliminating the need to traverse manually the collection’s internal implementation. This command’s biggest disadvantage is that it wasn’t updated to support the generic collections of .NET 2.0. It does support hash tables, which is the hardest collection to traverse. Here’s some sample output:
0:000> !dso
OS Thread Id: 0xbc8 (0)
ESP/REG Object Name
[…edited for brevity…]
0022f16c 023ecc50 System.Collections.Hashtable
0022f178 023ecc18 System.Collections.ArrayList
0022f17c 023ecbd0 System.Collections.Generic.List`1[[System.String, mscorlib]]
0:000> !dumpcollection 023ecc50
Going to dump the Collection passed.
Collection 0x023ecc50: System.Collections.Hashtable
Address MT Class Name
key: 0x023e9338 0x70540ae8 Masha
val: 0x023ecd24 0x70542d34 System.Int32
key: 0x023e931c 0x70540ae8 Sasha
val: 0x023ecd18 0x70542d34 System.Int32
0:000> !dumpcollection 023ecbd0
Going to dump the Collection passed.
0x023ecbd0 is not a supported Collection object
0:000> !dumpcollection 023ecc18
Going to dump the Collection passed.
Collection 0x023ecc18: System.Collections.ArrayList
[0] 023e931c
Name: System.String
MethodTable: 70540ae8
EEClass: 702fd65c
Size: 28(0x1c) bytes
GC Generation: 0
String: Sasha
Fields: […removed for brevity…]
[1] 023e9338
Name: System.String
MethodTable: 70540ae8
EEClass: 702fd65c
Size: 28(0x1c) bytes
GC Generation: 0
String: Masha
Fields: […removed for brevity…]
Next time, we’ll take a look at some additional object inspection commands, as well as commands tailored specifically for ASP.NET.
Almost a year ago, I delivered an MSDN Event on Parallel Programming in Visual Studio 2010. At the time, I used the Visual Studio 2010 Beta 1 but the demos worked fairly well.
Today, I delivered another version of the same talk, with only minor modifications. The difference is just that Visual Studio 2010 is out, and we’re talking about a mature framework which you should be using in your concurrent applications today.
You can download the demos (which haven’t changed :-)) and slides from here.
I mentioned several resources during the session which I think you might find useful:
A few days ago I had to debug a curious out-of-memory condition and encountered a pattern that you may find useful. The application in question consists of a set of WCF services that communicate with each other strictly through WCF channels. Occasionally, especially under heavy load, database operations start timing out, memory usage goes through the roof, and an OOM is thrown.
Instead of telling you in so many words what I did with the memory dumps, I wrote a simple repro which I’m going to work with. First of all, let’s run the application and simulate the heavy load with a Performance Monitor view showing us the managed memory usage:
Ah, the typical chainsaw graph. Memory goes up and down, but there are huge upwards spikes and the general trend is towards a memory exhaustion. Now is a good time to attach a debugger and look for some of those heavy memory consumers.
The bottom of !dumpheap –stat tells us the following:
5be06c28 861 481792 System.Object[]
001e7734 79316 1586320 MemoryExhaustingService.Product
5be4f9ac 82599 3070272 System.String
00703660 934 35016028 Free
5be54944 79406 164701720 System.Byte[]
Total 249998 objects
Oh my. Nigh 80,000 “Products”, and 80,000 byte arrays. Coincidence? Not in my repro applications :-) Let’s take a look at some of those:
0:028> .foreach (product {!dumpheap -mt 001e7734 -short}) {!objsize product}
sizeof(028afac0) = 1068 ( 0x42c) bytes (MemoryExhaustingService.Product)
sizeof(028afeec) = 1068 ( 0x42c) bytes (MemoryExhaustingService.Product)
sizeof(028b0318) = 1068 ( 0x42c) bytes (MemoryExhaustingService.Product)
sizeof(028b0744) = 1068 ( 0x42c) bytes (MemoryExhaustingService.Product)
sizeof(028b0b70) = 1068 ( 0x42c) bytes (MemoryExhaustingService.Product)
sizeof(028b0f9c) = 1068 ( 0x42c) bytes (MemoryExhaustingService.Product)
sizeof(028b13c8) = 1068 ( 0x42c) bytes (MemoryExhaustingService.Product)
sizeof(028b17f4) = 1068 ( 0x42c) bytes (MemoryExhaustingService.Product)
(MemoryExhaustingService.Product)
… [and so on, for another 79,000 objects]
So these “Products” are not really that innocent—each Product takes more than 1K of memory. Why?
0:029> !DumpObj 02d2a0ec
Name: MemoryExhaustingService.Product
MethodTable: 00247734
EEClass: 00310bdc
Size: 20(0x14) bytes
Fields:
MT Field Offset Type VT Attr Value Name
5be4f9ac 4000001 4 System.String 0 instance 02d2a4f4 <Name>k__BackingField
5be52978 4000002 c System.Int32 1 instance 3771 <Stock>k__BackingField
5be54944 4000003 8 System.Byte[] 0 instance 02d2a100 <Image>k__BackingField
0:029> !DumpObj 02d2a100
Name: System.Byte[]
MethodTable: 5be54944
EEClass: 5bb8af1c
Size: 1012(0x3f4) bytes
Array: Rank 1, Number of elements 1000, Type Byte Element Type:System.Byte
Fields:
None
What’s keeping these products and images alive then?
0:028> .foreach (product {!dumpheap -mt 001e7734 -short}) {!gcroot product}
Note: Roots found on stacks may be false positives. Run "!help gcroot" for
more info.
Scan Thread 0 OSTHread 774
Scan Thread 2 OSTHread 2284
Scan Thread 6 OSTHread 10e4
Scan Thread 7 OSTHread 6a4
Scan Thread 9 OSTHread 1ee4
Scan Thread 10 OSTHread 183c
Scan Thread 11 OSTHread 1db0
Scan Thread 12 OSTHread 2220
Scan Thread 14 OSTHread e38
Scan Thread 15 OSTHread 2128
Scan Thread 16 OSTHread 1310
Scan Thread 17 OSTHread 1f90
Scan Thread 18 OSTHread 1ce0
ESP:e7eed50:Root: 0f4ab69c(System.Object[])->
028afac0(MemoryExhaustingService.Product)
Scan Thread 19 OSTHread a30
Scan Thread 20 OSTHread 23ec
Scan Thread 8 OSTHread be8
Scan Thread 21 OSTHread 1f48
Scan Thread 22 OSTHread 22c0
Scan Thread 26 OSTHread 1980
Scan Thread 27 OSTHread 20ac
Note: Roots found on stacks may be false positives. Run "!help gcroot" for
more info.
Scan Thread 0 OSTHread 774
Scan Thread 2 OSTHread 2284
Scan Thread 6 OSTHread 10e4
Scan Thread 7 OSTHread 6a4
Scan Thread 9 OSTHread 1ee4
Scan Thread 10 OSTHread 183c
Scan Thread 11 OSTHread 1db0
Scan Thread 12 OSTHread 2220
Scan Thread 14 OSTHread e38
Scan Thread 15 OSTHread 2128
Scan Thread 16 OSTHread 1310
Scan Thread 17 OSTHread 1f90
Scan Thread 18 OSTHread 1ce0
ESP:e7eed50:Root: 0f4ab69c(System.Object[])->
028afeec(MemoryExhaustingService.Product)
Scan Thread 19 OSTHread a30
Scan Thread 20 OSTHread 23ec
Scan Thread 8 OSTHread be8
Scan Thread 21 OSTHread 1f48
Scan Thread 22 OSTHread 22c0
Scan Thread 26 OSTHread 1980
Scan Thread 27 OSTHread 20ac
Note: Roots found on stacks may be false positives. Run "!help gcroot" for
more info.
Scan Thread 0 OSTHread 774
Scan Thread 2 OSTHread 2284
Scan Thread 6 OSTHread 10e4
Scan Thread 7 OSTHread 6a4
Scan Thread 9 OSTHread 1ee4
Scan Thread 10 OSTHread 183c
Scan Thread 11 OSTHread 1db0
Scan Thread 12 OSTHread 2220
Scan Thread 14 OSTHread e38
Scan Thread 15 OSTHread 2128
Scan Thread 16 OSTHread 1310
Scan Thread 17 OSTHread 1f90
Scan Thread 18 OSTHread 1ce0
ESP:e7eed50:Root: 0f4ab69c(System.Object[])->
028b0318(MemoryExhaustingService.Product)
Scan Thread 19 OSTHread a30
Scan Thread 20 OSTHread 23ec
Scan Thread 8 OSTHread be8
Scan Thread 21 OSTHread 1f48
Scan Thread 22 OSTHread 22c0
Scan Thread 26 OSTHread 1980
Scan Thread 27 OSTHread 20ac
Note: Roots found on stacks may be false positives. Run "!help gcroot" for
more info.
Scan Thread 0 OSTHread 774
Scan Thread 2 OSTHread 2284
Scan Thread 6 OSTHread 10e4
Scan Thread 7 OSTHread 6a4
Scan Thread 9 OSTHread 1ee4
Scan Thread 10 OSTHread 183c
Scan Thread 11 OSTHread 1db0
Scan Thread 12 OSTHread 2220
Scan Thread 14 OSTHread e38
Scan Thread 15 OSTHread 2128
Scan Thread 16 OSTHread 1310
Scan Thread 17 OSTHread 1f90
Scan Thread 18 OSTHread 1ce0
ESP:e7eed50:Root: 0f4ab69c(System.Object[])->
028b0744(MemoryExhaustingService.Product)
Scan Thread 19 OSTHread a30
Scan Thread 20 OSTHread 23ec
Scan Thread 8 OSTHread be8
Scan Thread 21 OSTHread 1f48
Scan Thread 22 OSTHread 22c0
Scan Thread 26 OSTHread 1980
Scan Thread 27 OSTHread 20ac
Note: Roots found on stacks may be false positives. Run "!help gcroot" for
more info.
Scan Thread 0 OSTHread 774
Scan Thread 2 OSTHread 2284
Scan Thread 6 OSTHread 10e4
Scan Thread 7 OSTHread 6a4
Scan Thread 9 OSTHread 1ee4
Scan Thread 10 OSTHread 183c
Scan Thread 11 OSTHread 1db0
Scan Thread 12 OSTHread 2220
Scan Thread 14 OSTHread e38
Scan Thread 15 OSTHread 2128
Scan Thread 16 OSTHread 1310
Scan Thread 17 OSTHread 1f90
Scan Thread 18 OSTHread 1ce0
ESP:e7eed50:Root: 0f4ab69c(System.Object[])->
028b0b70(MemoryExhaustingService.Product)
Scan Thread 19 OSTHread a30
Scan Thread 20 OSTHread 23ec
Scan Thread 8 OSTHread be8
Scan Thread 21 OSTHread 1f48
Scan Thread 22 OSTHread 22c0
Scan Thread 26 OSTHread 1980
Scan Thread 27 OSTHread 20ac
… [and so on]
It seems that there are local references to all our Product instances, from various thread stacks. This is a good hint that it’s worth our while taking a look at the application’s threads.
0:029> !Threads
ThreadCount: 21
UnstartedThread: 0
BackgroundThread: 20
PendingThread: 0
DeadThread: 0
Hosted Runtime: no
[…edited for brevity…]
0 MTA
2 MTA (Finalizer)
6 MTA (Threadpool Completion Port)
8 MTA (Threadpool Completion Port)
9 MTA (Threadpool Completion Port)
10 MTA (Threadpool Completion Port)
11 MTA (Threadpool Worker)
12 MTA (Threadpool Worker)
14 MTA (Threadpool Worker)
15 MTA (Threadpool Worker)
16 MTA (Threadpool Worker)
17 MTA (Threadpool Worker)
18 MTA (Threadpool Worker)
19 MTA (Threadpool Worker)
20 MTA (Threadpool Worker)
21 MTA (Threadpool Worker)
7 MTA (Threadpool Worker)
22 MTA (Threadpool Completion Port)
23 MTA (Threadpool Completion Port)
24 MTA (Threadpool Worker)
25 MTA (Threadpool Worker)
Nothing particularly unusual here—it’s a WCF application, after all, so thread pool threads should not be surprising. How about the call stacks of these threads? I’m only looking at #18 here (which appears in the !gcroot output), but obviously I would have to look at the rest of them as well.
0:018> ~18s; !CLRStack
[…edited for brevity…]
OS Thread Id: 0x1bd0 (18)
[HelperMethodFrame_1OBJ: 1050e614] System.Threading.WaitHandle.WaitOneNative
System.Threading.WaitHandle.InternalWaitOne1050e6d8 System.Threading.WaitHandle.WaitOne
System.Runtime.TimeoutHelper.WaitOne
System.ServiceModel.Dispatcher.DuplexChannelBinder+SyncDuplexRequest.WaitForReply
System.ServiceModel.Dispatcher.DuplexChannelBinder.Request
System.ServiceModel.Channels.ServiceChannel.Call
System.ServiceModel.Channels.ServiceChannelProxy.InvokeService
System.ServiceModel.Channels.ServiceChannelProxy.Invoke
System.Runtime.Remoting.Proxies.RealProxy.PrivateInvoke
[TPMethodFrame: 1050ec30] MemoryExhaustingService.IInventoryService.GetAllProducts()
MemoryExhaustingService.HeartbeatManager.OnTimer
System.Threading._TimerCallback.TimerCallback_Context
System.Threading.ExecutionContext.runTryCode
[HelperMethodFrame_PROTECTOBJ: 1050f0d0] System.Runtime.CompilerServices.RuntimeHelpers.ExecuteCodeWithGuaranteedCleanup
System.Threading.ExecutionContext.RunInternal
System.Threading.ExecutionContext.Run
System.Threading._TimerCallback.PerformTimerCallback
1050f344 5f1021db [GCFrame: 1050f344]
1050f44c 5f1021db [DebuggerU2MCatchHandlerFrame: 1050f44c]
Hmm. This thread is inside a timer callback which invokes the HeartbeatManager.OnTimer method. This method, in turn, uses a WCF proxy to call the Inventory Service’s GetAllProducts operation, and blocks for the call to return.
I know that the WCF thread that’s supposed to be serving this operation is also within the same process, so I can look it up in the list of threads:
0:018> .shell -ci "~* e !CLRStack" findstr GetAllProducts
0616eb10 5f102356 [TPMethodFrame: 0616eb10] MemoryExhaustingService.IInventoryService.GetAllProducts()
08b5ec40 5f102356 [TPMethodFrame: 08b5ec40] MemoryExhaustingService.IInventoryService.GetAllProducts()
1050ec30 5f102356 [TPMethodFrame: 1050ec30] MemoryExhaustingService.IInventoryService.GetAllProducts()
080ee930 5f102356 [TPMethodFrame: 080ee930] MemoryExhaustingService.IInventoryService.GetAllProducts()
0822eba0 5f102356 [TPMethodFrame: 0822eba0] MemoryExhaustingService.IInventoryService.GetAllProducts()
This is interesting—these are all proxy calls, not the actual service implementations (I can tell because the name of the method is IInventoryService.GetAllProducts, not InventoryService.GetAllProducts). It means that the service isn’t actually processing a GetAllProducts request right now, and there are five threads waiting for it to reply to the GetAllProducts request. This is suspicious, so let’s see if we can find a thread with the InventoryService in it:
0:018> .shell -ci "~* e !CLRStack" findstr MemoryExhaustingService.InventoryService
07e3e8f0 00302483 MemoryExhaustingService.InventoryService.GetMyProducts()
There—the service is actually performing the GetMyProducts operation right now, and it must be configured with ConcurrencyMode.Single, so the rest of the threads are waiting. (Verifying the service concurrency mode is something you could do in the debugger, but it probably makes more sense checking it directly with the service code/configuration.)
So what are our findings so far?
- The Inventory Service is configured with ConcurrencyMode.Single, and currently processing the GetMyProducts operation.
- There are five threads invoked by a timer, all in the HeartbeatManager.OnTimer method, and they are waiting for the GetAllProducts operation to return. [There may be additional threads invoked by the timer.]
- Objects are not reclaimed because they are referenced (as local variables) from the timer threads. [This is not actually something I’ve proven here—I showed you that some of the Product instances are kept alive by one of the timer threads. Nonetheless, this statement is true—verifying it would only make this post longer.]
Let’s see what happens if we let the application run and the leak accumulate some more:
5be06c28 911 803216 System.Object[]
001c7734 154838 3096760 MemoryExhaustingService.Product
5be4f9ac 158121 5785864 System.String
00813660 2673 117781372 Free
5be54944 154934 257907356 System.Byte[]
0:039> !threads
ThreadCount: 31
UnstartedThread: 0
BackgroundThread: 30
PendingThread: 0
DeadThread: 0
Hosted Runtime: no
[…edited for brevity…]
0 MTA
2 MTA (Finalizer)
6 MTA (Threadpool Completion Port)
7 MTA (Threadpool Completion Port)
8 MTA (Threadpool Completion Port)
9 MTA (Threadpool Completion Port)
10 MTA (Threadpool Completion Port)
11 MTA (Threadpool Worker)
12 MTA (Threadpool Worker)
14 MTA (Threadpool Worker)
15 MTA (Threadpool Worker)
16 MTA (Threadpool Worker)
17 MTA (Threadpool Worker)
18 MTA (Threadpool Worker)
19 MTA (Threadpool Worker)
20 MTA (Threadpool Worker)
21 MTA (Threadpool Worker)
22 MTA (Threadpool Worker)
23 MTA (Threadpool Worker)
24 MTA (Threadpool Worker)
25 MTA (Threadpool Worker)
26 MTA (Threadpool Worker)
27 MTA (Threadpool Worker)
31 MTA (Threadpool Worker)
32 MTA (Threadpool Worker)
33 MTA (Threadpool Worker)
34 MTA (Threadpool Worker)
35 0 MTA (Threadpool Worker)
36 0 MTA (Threadpool Worker)
37 MTA (Threadpool Worker)
38 MTA (Threadpool Worker)
Oh boy, even more Products and even more threads! Out of sheer curiosity, how many of those are inside the OnTimer method?
0:039> .shell -ci "~* e !CLRStack" findstr OnTimer
065aee80 00230c49 MemoryExhaustingService.HeartbeatManager.OnTimer
0632ed60 00230c49 MemoryExhaustingService.HeartbeatManager.OnTimer
0ad2edd0 00230c34 MemoryExhaustingService.HeartbeatManager.OnTimer
076deac0 00230c49 MemoryExhaustingService.HeartbeatManager.OnTimer
0931ee80 00230c49 MemoryExhaustingService.HeartbeatManager.OnTimer
10c8e8a0 00230c49 MemoryExhaustingService.HeartbeatManager.OnTimer
0be7eb00 00230c49 MemoryExhaustingService.HeartbeatManager.OnTimer
0ac2ed60 00230c49 MemoryExhaustingService.HeartbeatManager.OnTimer
0a57e990 00230c34 MemoryExhaustingService.HeartbeatManager.OnTimer
0a68ea30 00230c34 MemoryExhaustingService.HeartbeatManager.OnTimer
0a7ce6a0 00230c34 MemoryExhaustingService.HeartbeatManager.OnTimer
0a9fefc0 00230c49 MemoryExhaustingService.HeartbeatManager.OnTimer
0e7deb70 00230c49 MemoryExhaustingService.HeartbeatManager.OnTimer
0c0ae8c0 00230c49 MemoryExhaustingService.HeartbeatManager.OnTimer
0c22eb10 00230c49 MemoryExhaustingService.HeartbeatManager.OnTimer
094bee80 00230c49 MemoryExhaustingService.HeartbeatManager.OnTimer
097bedf0 00230c34 MemoryExhaustingService.HeartbeatManager.OnTimer
099aeca0 00230c34 MemoryExhaustingService.HeartbeatManager.OnTimer
07c3e840 00230c34 MemoryExhaustingService.HeartbeatManager.OnTimer
07e5e860 00230c34 MemoryExhaustingService.HeartbeatManager.OnTimer
07f6e790 00230c34 MemoryExhaustingService.HeartbeatManager.OnTimer
0806e790 00230c34 MemoryExhaustingService.HeartbeatManager.OnTimer
0822eab0 00230c34 MemoryExhaustingService.HeartbeatManager.OnTimer
Quite a few, and growing! This brings us to the conclusion:
The Inventory Service is configured with ConcurrencyMode.Single, and the GetAllProducts/GetMyProducts operations are rather lengthy. There is a heartbeat timer configured to retrieve the list of products at relatively short intervals, and under heavy load the Inventory Service returns results at a slower rate than the rate at which the timer fires. As a result, timer threads accumulate inside Heartbeat.OnTimer, keeping Product instances from being collected because they have a local variable referencing them.
Some possible recommendations would be decreasing the timer interval, making sure there is only one timer invocation at a given time (e.g. using Monitor.TryEnter), finding a way to make the Inventory Service use the Multiple concurrency mode, or removing the need for the heartbeat threads to retrieve and maintain a large number of products while performing a blocking operation (service call).
In my original debugging session, the story was slightly more complicated because there were also dozens of application threads blurring the picture, and the heartbeat threads were busy accessing multiple WCF services and databases. The general picture was the same nevertheless—heartbeat threads, which are supposed to be responsible for the application’s well-being, served the opposite purpose by creating increasing load on system components and bringing the system down by exhausting all memory. I think there’s even a philosophical angle somewhere in all of this :-)
When a thread makes a method call through an appropriately marshaled COM proxy that points to a thread in a different STA (Single-Threaded Apartment), ole32.dll kicks in and implements the minute details of marshaling input parameters across the required boundary, waiting for the call to return, and unmarshaling the return value and output parameters.
In a debugger, a thread making a COM call to another STA will have a native call stack similar to the following:
0:002> kb
ChildEBP RetAddr Args to Child
... ntdll!ZwWaitForSingleObject+0x15
... KERNELBASE!WaitForSingleObjectEx+0x98
... KERNEL32!WaitForSingleObjectExImplementation+0x75
... KERNEL32!WaitForSingleObject+0x12
00def1d8 7693a819 0056fdc8 ... ole32!GetToSTA+0xad
... ole32!CRpcChannelBuffer::SwitchAptAndDispatchCall+0x140
00def2e8 7682d0e5 00599ca8 ... ole32!CRpcChannelBuffer::SendReceive2+0xef
... ole32!CAptRpcChnl::SendReceive+0xaf
... ole32!CCtxComChnl::SendReceive+0x95
... ole32!NdrExtpProxySendReceive+0x49
... RPCRT4!NdrpProxySendReceive+0xe
... RPCRT4!NdrClientCall2+0x1a6
The first parameter of ole32!GetToSTA [3] is an internal structure [1] that contains the process ID and thread ID of the STA thread for which the transition is currently waiting. The same structure is also the 7th DWORD field of the first parameter of ole32!CRpcChannelBuffer::SendReceive2 [2].
0:002> dd 00599ca8 L8
00599ca8 7684f3b8 768280dc 00000003 0000002a
00599cb8 00521540 00000000 0056fdc8 00570d08
0:002> dd 0056fdc8 L4
0056fdc8 0056fe48 769468f8 000020b4 00001404
In the second output, the 3rd and 4th DWORDs are the process ID and thread ID, respectively. If the COM call is stuck, you can switch to that process/thread and see what it’s doing—it’s probably in a non-pumping wait, which precludes the COM infrastructure from receiving the incoming call. [0]
References:
[0] .NET Debugging and C++ Debugging Resources
[1] The OXIDEntry structure
[2] Find the STA thread we’re switching to in SendReceive2
[3] Find the STA thread we’re switching to in GetToSTA
The following is a summary of tools and resources that you might be interested in after taking the .NET Debugging and/or C++ Debugging courses we offer at Sela.
[Shameless plug: If you haven’t taken these courses yet, I strongly suggest that you check them out. Between the two of them they have more than 20 hands-on debugging exercises which basically guarantee that you’re going to come out a WinDbg expert and be able to analyze dumps, solve problems in production, pinpoint memory leaks, and so on.]
First of all, the tools you are going to need. This is also a list of what I ask system administrators to install when giving these courses in a disconnected environment:
Now the resources you might find handy. I organized these by exercise, so that for each exercise there is at least one reference you might find useful:
- Setting up symbols
- Configuring symbols in a connected environment (KB)
- Obtaining Windows symbol packages
- How to verify symbols with symchk
- Diagnosing a managed exception
- Configuring automatic crash dumps
- Using !PrintException and !CLRStack
- Managed deadlock with Monitors
- Using !SyncBlk and SOSEX’s !dlk
- Analyzing Monitor-based deadlocks on 64-bit
- Another way to tell the sync object your thread waits for
- Managed memory leak with static event
- Diagnosing a memory leak using SOS’s !DumpHeap, CLR Profiler, and Hawkeye
- Inspecting a managed heap with !DumpHeap
- Diagnosing a memory leak caused by event handlers
- Managed memory leak with finalizer
- Unblock my finalizer
- Don’t blindly count on a finalizer
- File access problem with Process Monitor
- .NET file access in Process Monitor
- The case of the slow logons (Process Monitor)
- Application compatibility fix
- Creating a registry redirection (VirtualRegistry)
- Version lie shims
- Using the CorrectFilePaths shim
- Diagnosing assembly loading with Fusion Log Viewer
- Using fuslogvw to diagnose binding issues
- Assembly private bin path pitfall
- Finalization race condition
- Finalizer vs. application
- Reader-writer lock deadlock
- Implementing a RWL using a semaphore
- COM and STA memory leak
- Find the STA thread to which we’re switching from SendReceive2
- Find the STA thread to which we’re switching from GetToSTA
- Inspecting the OXIDEntry structure in GetToSTA
- Comparing out-of-memory exceptions
- Memory display tool for virtual memory and GC heap
- Unmanaged memory leak with UMDH
- How to use umdh to find memory leaks
- GetProcessHeap and _get_heap_handle
- Unmanaged deadlock with critical sections
- Exploring the internals of critical sections
- Using !cs vs. !locks (with case studies)
- Unmanaged heap corruption with Application Verifier
- Exploring heap-based buffer overflows
- Using pageheap.exe (KB)
- Unmanaged stack corruption
- Common stack analysis commands
- File leak with Process Monitor and handle tracing
- See handle open call stacks
- The oh.exe tool
- Invalid handle problems with handle tracing
- Use !htrace to detect an invalid handle reference and when it was closed
- Handle Application Verifier stops
- C++ runtime checks
- /RTC compiler switch
- Multi-object deadlock with WCT and local kernel debugging
- Vista Wait Chain Traversal
- WCT debugging extension (also on CodePlex)
- Diagnosing a C++ exception
- Decoding the parameters of a thrown C++ exception
- Exception-related commands
Finally, there’s my three year old list of debugging tools that could also be considered useful.
Configuring WCF message quotas on the server and client sides is not a trivial task. There are quite a few settings that you can tweak, including limits for a single string’s length in a message, the number of objects in the serialization graph, the serialization depth, and the array size.
However, there’s one limit my service hit a few days ago that I wasn’t at all aware of—I didn’t even realize there was a reason for it to exist. Consider the following service method:
public string Foo(bool throwFault, int stringLength)
{
string s = new string('A', stringLength);
if (throwFault)
throw new FaultException<string>(s);
return s;
}
And the following service method invocation:
proxy.Foo(false, 10000);
The service host is using the NetTcpBinding, with the default configuration settings. The result of the previous line would be the following exception:
System.ServiceModel.CommunicationException: Error in deserializing body of reply message for operation 'Foo'. The maximum string content length quota (8192) has been exceeded while reading XML data. This quota may be increased by changing the MaxStringContentLength property on the XmlDictionaryReaderQuotas object used when creating the XML reader.
All righty then, off we go and change the MaxStringContentLength property to 200K. The above now works, but the following fails:
proxy.Foo(false, 100000);
This time, we’re hitting this:
System.ServiceModel.CommunicationException: The maximum message size quota for incoming messages (65536) has been exceeded. To increase the quota, use the MaxReceivedMessageSize property on the appropriate binding element.
Oh, now we have to tune the maximum message side on the receiving binding. After doing that, the above works, but the following fails:
proxy.Foo(true, 100000);
With the only difference being that this time, we’re throwing a fault with a 100000-character message, instead of simply returning it from the service operation. Evidently, there is some difference here, as the exception reads:
System.ServiceModel.QuotaExceededException: The size necessary to buffer the XML content exceeded the buffer quota.
And the call stack is on the client side:
System.Runtime.BufferedOutputStream.WriteCore(…)
System.Runtime.BufferedOutputStream.Write(…)
System.Xml.XmlBinaryNodeWriter.FlushBuffer()
System.Xml.XmlStreamNodeWriter.UnsafeWriteUTF8Chars(…)
System.Xml.XmlBinaryNodeWriter.UnsafeWriteText(…)
System.Xml.XmlBinaryNodeWriter.WriteText(…)
System.Xml.XmlBinaryNodeWriter.WriteEscapedText(…)
System.Xml.XmlBaseWriter.WriteChars(…)
System.Xml.XmlBinaryWriter.WriteTextNode(…)
System.Xml.XmlDictionaryWriter.WriteNode(…)
System.ServiceModel.Channels.ReceivedFault.CreateFault12Driver(…)
System.ServiceModel.Channels.MessageFault.CreateFault(…)
System.ServiceModel.Channels.ServiceChannel.HandleReply(…)
System.ServiceModel.Channels.ServiceChannel.Call(…)
System.ServiceModel.Channels.ServiceChannelProxy.InvokeService(…)
System.ServiceModel.Channels.ServiceChannelProxy.Invoke(…)
After using Reflector to inspect the implementation of ServiceChannel.HandleReply, I realized that there’s another quota being used here—the client runtime’s maximum fault size, i.e. the maximum size of a fault message that the client can process.
Modifying a property of the client runtime is not completely trivial, and the solution I’m showing below uses a contract behavior. It’s also possible to accomplish using an endpoint behavior, or a channel factory customization.
[AttributeUsage(AttributeTargets.Interface, AllowMultiple = false)]
public sealed class MaximumFaultSizeAllowedAttribute :
Attribute, IContractBehavior
{
private readonly int _maxFaultSize;
public MaximumFaultSizeAllowedAttribute(
int maxFaultSize)
{
_maxFaultSize = maxFaultSize;
}
public void Validate(
ContractDescription contractDescription,
ServiceEndpoint endpoint)
{
}
public void ApplyDispatchBehavior(
ContractDescription contractDescription,
ServiceEndpoint endpoint,
DispatchRuntime dispatchRuntime)
{
}
public void ApplyClientBehavior(
ContractDescription contractDescription,
ServiceEndpoint endpoint,
ClientRuntime clientRuntime)
{
clientRuntime.MaxFaultSize = _maxFaultSize;
}
public void AddBindingParameters(
ContractDescription contractDescription,
ServiceEndpoint endpoint,
BindingParameterCollection bindingParameters)
{
}
}
Placing this attribute on the service contract configures appropriately the maximum fault size allowed on the client side.
[This behavior is obscure enough to warrant someone opening a Connect bug claiming that reader quotas are ignored when throwing exceptions. The bug was closed two days later.]