A curious case: CLR/COM Interop leak

A curious case: CLR/COM Interop leak

• UNCATEGORIZED
• .NET, COM, INTEROP, PRODUCTION DEBUGGING, WINDBG
• LEAVE A COMMENT

Background

A customer asked me a question last week: in CLR-COM interop case, who is responsible to free up a string returned from COM? My understanding was that the interop layer setup by .NET will automatically take care of this. However, I thought a mock test would not do any harm. To my surprise this test actually opened up the proverbial ‘can of worms’ and I thought I would share my experience with you!

Prerequisite reading

There was a lot of detailed debugging stuff we will cover here, and it assumes some basics. For those who are not aware of the basics, I recommend you first consume the following.

• Free training video series- .NET Debugging for production environments
• Production Debugging for .NET Framework Applications (there was a PDF version of this guide, but the link seems broken – Bing for ‘DBG_download.pdf’ if you want to look for it.)
• For disassembly (e.g. how does ebp+8 map to parameters) please read Under the Hood, MSJ February 1998 – Microsoft Corporation and Annotated x86 Disassembly – Microsoft Corporation- Software

 

Test setup: COM Server

We have an in-process ATL COM server which exposes an interface and a single method, SayHello. Here is the IDL interface for this method:

interface Imyclass : IDispatch{
    [id(1)] HRESULT SayHello([out] BSTR* hellostr);
};

And here is the implementation:

STDMETHODIMP Cmyclass::SayHello(BSTR* hellostr)
{
   *hellostr = SysAllocString(L"Hello World");

 

   return S_OK;
}

As you can see, this is no rocket science, we are allocating a BSTR inside the component and returning it to the caller. Therefore as per COM conventions the caller should free this up.

Test setup: C# client

We have a managed client written as a C# console application. A reference is added to the COM library, cominteropLib and that allows us to create instances of myclass:

static void Main(string[] args)
        {
            Console.ReadKey();

 

            string sout = "";
            myclass cls = new myclass();

 

            int i = 0;
            while (true)
            {
                cls.SayHello(ref sout);

 

                if (i % 100000 == 0)
                {
                    System.Threading.Thread.Sleep(1000);
                    Console.Write(sout);
                }               

             i++;
            }

Observations

So when we run the C# application, and plot Virtual, Private Bytes and also # Managed bytes for this process, here is the observed trend:

Advertisements

 

REPORT THIS AD

As you can see, the Private Bytes increases steadily, but the amount of managed bytes recorded is not even registering (almost 0 at this scale of the graph.) Generally this indicates the leak is in unmanaged allocations, as you can see in Using Perfmon to Diagnose Application Issues – 02.

    

Tracking the unmanaged leak

The best way to track down unmanaged leaks is to use DebugDiag 1.2. We did that and ran the Memory Analysis (native code only) to find out the call stacks with the most outstanding unmanaged allocations. Here are the relevant sections from the DebugDiag report:

 

mscorlib.ni.dll is responsible for 73.24 MBytes worth of outstanding allocations. The following are the top 2 memory consuming functions: mscorlib_ni+2c70aa: 73.24 MBytes worth of outstanding allocations.

 

Memory manager statistics by allocation size
OLE automation BSTR memory manager :  73.24 MBytes
Heap memory manager : 622.98 KBytes

So from this, it is clear that we are somehow leaking BSTRs. Let us save the call stack of the leaked allocation, and come back to it later (only the top few frames are reproduced for brevity.)

Call stack sample 1

 

Address   0x00650048
Allocation Time   00:00:10 since tracking started
Allocation Size   24 Bytes

Function   Source   Destination
mscorlib_ni+2c70aa      
clr+5d80      
mscorlib_ni+2c70aa      
clr+5d80      
mscorlib_ni+24bc9d      
clr+2ec3      0xAC07C8
clr+21db      
clr!LogHelp_TerminateOnAssert+301ec      
clr!LogHelp_TerminateOnAssert+74a40      
0x1DC030      
ConsoleApplication1+281e      
ConsoleApplication1+281e      
ConsoleApplication1+281d      
ConsoleApplication1+281b      

We will come back to this later.

Manually tracking the leak

Normally, we will just use the above call stack and drill down into the root cause. But I wanted to show you some other debugging methods which can be very useful. First, we will check if SysFreeString() is being called at all. Next, we will also dump the address of the BSTR allocated by SysAllocString() inside the COM component. We will compare these and check if we do release the BSTR which the COM component is allocating.

Checking SysAllocString / SysFreeString pairs

We will use conditional breakpoints in WinDbg to get this debug output. Here are the breakpoints:

• bp `cominterop!myclass.cpp:21` ".echo ‘SysAllocString’; dd poi(hellostr) L1;g"

 

• bp OLEAUT32!SysFreeString+0x7 ".echo ‘SysFreeString’; dd ebp+8 L1; g"

A quick explanation of these breakpoints is in order. The first one is a normal location breakpoint set on the line number 21 of myclass.cpp. We can easily do this because we have the source code of the COM component. In the case of the second (SysFreeString) breakpoint, we are going as per the disassembly knowledge, and guessing that [ebp+8] is actually the input parameter. Here is the disassembly of oleaut32!SysFreeString for your reference:

0:004> u oleaut32!SysFreeString
OLEAUT32!SysFreeString:
76333e40 8bff            mov     edi,edi
76333e42 55              push    ebp
76333e43 8bec            mov     ebp,esp
76333e45 51              push    ecx
76333e46 56              push    esi
76333e47 8b7508          mov     esi,dword ptr [ebp+8]    <— This is the second breakpoint. We will dump [ebp+8] here.
76333e4a 85f6            test    esi,esi
76333e4c 743d            je      OLEAUT32!SysFreeString+0x6c (76333e8b)

Both breakpoints contain commands to be executed when the breakpoint is hit. For the breakpoint in myclass, we will dump the address of the BSTR being returned by SysAllocString. For the SysFreeString we will dump the contents of location ebp+8 (so that we get the BSTR address being passed in.)

Here is the sample output from these breakpoints (snipped and reformatted to suit this blog post)

‘SysAllocString’ 0029f090  0045705c
‘SysFreeString’ 0029efdc  0045705c
‘SysAllocString’ 0029f090  00457094
‘SysFreeString’ 0029efdc  00457094
‘SysAllocString’ 0029f090  004570cc
‘SysFreeString’ 0029efdc  004570cc
‘SysAllocString’ 0029f090  00457104
‘SysFreeString’ 0029efdc  00457104
‘SysAllocString’ 0029f090  0045713c
‘SysFreeString’ 0029efdc  0045713c

As you can see from the above, we are very clearly freeing up the BSTR which is being returned by the COM component (values which are in bold). Next, let us see who is actually freeing those BSTRs (note: the ‘!clrstack’ and kb commands are executed manually when we hit the breakpoint on SysFreeString+0x7)

0:000> !clrstack;kb
OS Thread Id: 0xad8 (0)
Child SP IP       Call Site
0029efe4 76333e47 [InlinedCallFrame: 0029efe4] Microsoft.Win32.Win32Native.SysFreeString(IntPtr)
0029efe0 6ac0c7d5 System.StubHelpers.BSTRMarshaler.ClearNative(IntPtr)
0029f020 002a033e DomainBoundILStubClass.IL_STUB_CLRtoCOM(System.String ByRef)
0029f028 002a0121 [InlinedCallFrame: 0029f028] cominteropLib.Imyclass.SayHello(System.String ByRef)
0029f0c8 002a0121 ConsoleApplication1.Program.Main(System.String[]) [c:TempcominteropConsoleApplication1Program.cs @ 22]
0029f330 6c5421db [GCFrame: 0029f330]

The above is the managed call stack, which seems to suggest that the CLR-COM interop stub is automatically freeing up the BSTR returned by our COM component. FYI, you can look at the implementation of the StubHelpers.BSTRMarshaler class from the .NET Reference Source. FWIW, given below is the native call stack, just for your reference (there is not too much value add from it.)

ChildEBP RetAddr  Args to Child             
0029efd4 6ac0c7d5 0045713c 7058594b 6c545d80 OLEAUT32!SysFreeString+0x7
WARNING: Stack unwind information not available. Following frames may be wrong.
0029f040 6abf7774 0029f0c0 00000000 000d387c mscorlib_ni+0x26c7d5
0029f104 6c5421db 0029f148 0007281d 0029f190 mscorlib_ni+0x257774
0029f114 6c564a2a 0029f1e0 00000000 0029f1b0 clr+0x21db
0029f190 6c564bcc 0029f1e0 00000000 0029f1b0 clr!CoUninitializeEE+0x6862
0029f2c8 6c564c01 000dc030 0029f394 0029f354 clr!CoUninitializeEE+0x6a04
0029f2e4 6c564c21 000dc030 0029f394 0029f354 clr!CoUninitializeEE+0x6a39
0029f2fc 6c62ce82 0029f354 70d6a23c 00000000 clr!CoUninitializeEE+0x6a59
0029f460 6c62cf90 000d3810 00000001 0029f49c clr!GetCLRFunction+0xc08
0029f6c8 6c62cda4 00000000 70d6adf0 00000000 clr!GetCLRFunction+0xd16
0029fbac 6c62d199 00070000 00000000 70d6aa5c clr!GetCLRFunction+0xb2a
0029fc00 6c62d09a 00070000 70d6aa10 00000000 clr!GetCLRFunction+0xf1f
0029fc4c 6c6aaf00 70d6aad8 00000000 7737903b clr!GetCLRFunction+0xe20
0029fc84 6e2555ab 6c6aaee4 0029fca0 6fb47f16 clr!CorExeMain+0x1c
0029fc90 6fb47f16 00000000 6e250000 0029fcb4 mscoreei!CorExeMain+0x38
0029fca0 6fb44de3 00000000 7737d0e9 7ffda000 mscoree!CreateConfigStream+0x13f
0029fcb4 778919bb 7ffda000 771e5a5e 00000000 mscoree!CorExeMain+0x8
0029fcf4 7789198e 6fb44ddb 7ffda000 ffffffff ntdll!__RtlUserThreadStart+0x23
0029fd0c 00000000 6fb44ddb 7ffda000 00000000 ntdll!_RtlUserThreadStart+0x1b

Clueless?

So, what do we have so far? We know from DebugDiag that somehow we are leaking BSTR memory. But on the other hand from the live debug trace we have also found that the BSTR being returned from the COM component is indeed being freed by the CLR-COM interop layer. So what gives? Who is the other source of the leaked BSTRs?

For answering that, we will go back to our DebugDiag output. In that, it says the function mscorlib_ni+2c70aa was responsible for the native leak. Let us set a breakpoint there and check what that really means in managed code world:

0:000> bp mscorlib_ni+2c70aa
0:000> g
Breakpoint 2 hit
eax=0045713c ebx=00000000 ecx=0041c970 edx=00000006 esi=003e8680 edi=00000000
eip=6ac670aa esp=0029efbc ebp=0029effc iopl=0         nv up ei pl zr na pe nc
cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000             efl=00000246
mscorlib_ni+0x2c70aa:
6ac670aa c6460801        mov     byte ptr [esi+8],1         ds:0023:003e8688=00

Once the above breakpoint is hit, we can view the managed call stack. This time we will view it with local and parameter information (-l and –p).

0:000> !clrstack -l -p
OS Thread Id: 0xad8 (0)
Child SP IP       Call Site
0029efbc 6ac670aa DomainNeutralILStubClass.IL_STUB_PInvoke(Byte[], UInt32)
    PARAMETERS:
        <no data>
        <no data>

 

0029efc0 6abeb1e7 [InlinedCallFrame: 0029efc0] Microsoft.Win32.Win32Native.SysAllocStringByteLen(Byte[], UInt32)
0029f004 6abeb1e7 System.StubHelpers.BSTRMarshaler.ConvertToNative(System.String, IntPtr)
    PARAMETERS:
        strManaged (<CLR reg>) = 0x01e620a0
        pNativeBuffer = <no data>
    LOCALS:
        <no data>
        <CLR reg> = 0x00000000
        0x0029f008 = 0x00000016
        <no data>
        <no data>
        <no data>
        <no data>

 

0029f024 002a020e DomainBoundILStubClass.IL_STUB_CLRtoCOM(System.String ByRef)
    PARAMETERS:
        this = <no data>
        <no data>

 

0029f028 002a0121 [InlinedCallFrame: 0029f028] cominteropLib.Imyclass.SayHello(System.String ByRef)
0029f0c8 002a0121 ConsoleApplication1.Program.Main(System.String[])*** WARNING: Unable to verify checksum for ConsoleApplication1.exe
  [c:TempcominteropConsoleApplication1Program.cs @ 22]
    PARAMETERS:
        args (0x0029f0fc) = 0x01e3af40
    LOCALS:
        0x0029f0f8 = 0x01e620a0
        0x0029f0d0 = 0x01e3bf30
        0x0029f0f4 = 0x000010ee
        0x0029f0f0 = 0x00000001

 

0029f330 6c5421db [GCFrame: 0029f330]   

 

 

 

What I want to highlight here is that the local variable at stack address 0x0029f0f8 (with a actual object address of 0x01e620a0) is actually our local string sout:

 

0:000> !do 0x01e620a0
Name:        System.String
MethodTable: 6acbf9ac
EEClass:     6a9f8bb0
Size:        36(0x24) bytes
File:        C:WindowsMicrosoft.NetassemblyGAC_32mscorlibv4.0_4.0.0.0__b77a5c561934e089mscorlib.dll
String:      Hello World
Fields:
      MT    Field   Offset                 Type VT     Attr    Value Name
6acc2978  40000ed        4         System.Int32  1 instance       11 m_stringLength
6acc1dc8  40000ee        8          System.Char  1 instance       48 m_firstChar
6acbf9ac  40000ef        8        System.String  0   shared   static Empty
    >> Domain:Value  003b0c10:01e31228 <<

This local variable is what is finally passed into BSTRMarshaler.ConvertToNative (the strManaged parameter is 0x01e620a0, which is the local sout string itself.)

Eureka!

So this, means that while calling the COM component, the CLR-COM interop layer is ‘helping’ us by wrapping our .NET string (the variable called sout) as a BSTR and then invoking the component. Evidently that is not getting freed up. On source code inspection, it becomes obvious that maybe we are missing a call to set sout = null after the call to the COM component. On fixing the code, the ‘leak’ goes away. Here is a comparison of the IL code before and after the fix.

Before the fix

.method private hidebysig static void  Main(string[] args) cil managed
{
  .entrypoint
  // Code size       56 (0x38)
  .maxstack  2
  .locals init ([0] string sout,
           [1] class cominteropLib.myclass cls,
           [2] bool CS$4$0000)
  IL_0000:  nop
  IL_0001:  call       valuetype [mscorlib]System.ConsoleKeyInfo [mscorlib]System.Console::ReadKey()
  IL_0006:  pop
  IL_0007:  ldstr      ""
  IL_000c:  stloc.0
  IL_000d:  ldstr      "8F69F29F-97C3-4228-9D03-6499E88C6F38"
  IL_0012:  newobj     instance void [mscorlib]System.Guid::.ctor(string)
  IL_0017:  call       class [mscorlib]System.Type [mscorlib]System.Type::GetTypeFromCLSID(valuetype [mscorlib]System.Guid)
  IL_001c:  call       object [mscorlib]System.Activator::CreateInstance(class [mscorlib]System.Type)
  IL_0021:  castclass  cominteropLib.myclass
  IL_0026:  stloc.1
  IL_0027:  br.s       IL_0034
  IL_0029:  nop
  IL_002a:  ldloc.1
  IL_002b:  ldloca.s   sout
  IL_002d:  callvirt   instance void cominteropLib.Imyclass::SayHello(string&)
  IL_0032:  nop
  IL_0033:  nop
  IL_0034:  ldc.i4.1
  IL_0035:  stloc.2
  IL_0036:  br.s       IL_0029
} // end of method Program::Main

After the fix

.method private hidebysig static void  Main(string[] args) cil managed
{
  .entrypoint
  // Code size       58 (0x3a)
  .maxstack  2
  .locals init ([0] string sout,
           [1] class cominteropLib.myclass cls,
           [2] bool CS$4$0000)
  IL_0000:  nop
  IL_0001:  call       valuetype [mscorlib]System.ConsoleKeyInfo [mscorlib]System.Console::ReadKey()
  IL_0006:  pop
  IL_0007:  ldstr      ""
  IL_000c:  stloc.0
  IL_000d:  ldstr      "8F69F29F-97C3-4228-9D03-6499E88C6F38"
  IL_0012:  newobj     instance void [mscorlib]System.Guid::.ctor(string)
  IL_0017:  call       class [mscorlib]System.Type [mscorlib]System.Type::GetTypeFromCLSID(valuetype [mscorlib]System.Guid)
  IL_001c:  call       object [mscorlib]System.Activator::CreateInstance(class [mscorlib]System.Type)
  IL_0021:  castclass  cominteropLib.myclass
  IL_0026:  stloc.1
  IL_0027:  br.s       IL_0036
  IL_0029:  nop
  IL_002a:  ldloc.1
  IL_002b:  ldloca.s   sout
  IL_002d:  callvirt   instance void cominteropLib.Imyclass::SayHello(string&)
  IL_0032:  nop
  IL_0033:  ldnull
  IL_0034:  stloc.0
  IL_0035:  nop
  IL_0036:  ldc.i4.1
  IL_0037:  stloc.2
  IL_0038:  br.s       IL_0029
} // end of method Program::Main

The main difference as you can see is the assignment of null to the sout variable (that is what the IL instruction stloc.0 does).

Conclusions

This was a very interesting walkthrough and I would like to summarize the steps:

1. Use Performance Monitor to distinguish between a managed and unmanaged origin leak.
2. For unmanaged leaks, you need to track those using DebugDiag’s leak tracking rule.
3. Normally, for a pure unmanaged origin leak, the output from DebugDiag will give you the offending line of code.
4. However in this case because the offending line of code is actually in an auto-generated CLR-COM stub, we cannot resolve it statically.
5. Live debugging by setting the breakpoint on the native code address reported by DebugDiag gave us the opportunity to view the managed call stack leading to this unmanaged leak.

 

Recommendation

If you are reusing BSTRs across COM method calls, always set the strings returned to you by COM components explicitly to null in C# code before calling your COM method. That will allow the CLR-COM interop stub to correctly skip making the ConvertToNative call for the input BSTR, and therefore avoid the leak.

Well, I hope you really enjoyed this post. It was hard work for me but I enjoyed tracking it down. I hope you also enjoyed it as much as I did. Please drop a comment and see you next time!