.NET WCF w3wp native memory leak and 18k dynamic assemblies of 0 sizes in loader heap

Question

Our WCF service showed an Instance of large memory usage so we took a full memory dump to identify the issue.

Operating System   Windows Server 2008 R2Service Pack 1 
Number Of Processors   4 
Process Image   c:\Windows\System32\inetsrv\w3wp.exe 
System Up-Time   40 day(s) 09:23:09 
Process Up-Time   14 day(s) 11:49:01 
.NET 4.0
Processor Type   X64 
Process Bitness   64-Bit

Helicopter view of the problem from DebugDiag report.

1. Process was garbage collecting, so as per warning I should not be trusting all the output from !heap commands.

2. Gc heap : 1.37 GBytes

3. .NET Cache size is 750Mb,

   Virtual Memory Details : Virtual Allocations : 17.45 Gb Loaded Modules : 208.68 Mb Threads : 25 Mb Native Heaps : 3.06 Gb (I am concerned about this.)

From above 3.02 Gb is present on Heap 0x003f0000 alone. We have good amount of traffic, that way 1.3 gb Gc heap size feels normal to me. Also we have machine with 32 gb ram and 64bit address space, so Cache size of 750 mb is acceptable. As per the size of Native heap, I feel this is native memory leak.

DebugDiag warning : There are 18149 dynamic assemblies loaded in the dump file.

Help links :
.NET Memory Leak: XmlSerializing your way to a Memory Leak
Analysis - We do use XmlSerialisers but they are cached, that way they are created only once.

.NET Memory Leak: XslCompiledTransform and leaked dynamic assemblies
We seems to have same kind of problem described in this blog post. All these 18149 dynamic assemblies are of 0 sizes. So I cannot dump them to get details. Also we don't use Xsl transform any where in this application. So these assemblies are not due to Xsl transforms.

Some more stats :
Related object counts :

System.Reflection.Emit.InternalModuleBuilder -----   1.11 MBytes    (18149 objects )
System.Reflection.Emit.InternalAssemblyBuilder ----- 992.52 KBytes    (18149 objects ) 
System.Reflection.Emit.__FixupData[]  ----------   595.41 KBytes    (752 objects )
System.Reflection.Emit.GenericFieldInfo  ----------  580.03 KBytes    (18561 objects )
System.Reflection.RuntimeMethodInfo  ----------   1.2 MBytes    (11276 objects )
System.RuntimeType --------------------     1.13 MBytes    (21228 objects )

Top Objects in the Finalizer queue

System.Reflection.Emit.DynamicResolver - 379 System.Reflection.Emit.DynamicResolver+DestroyScout - 271

Application Domain Statistics
Domain - Default - 13 assemblies - size : 89,677,824 (90 Mb ~) Domain - ROOT/tv/Engine1 - 18236 Assemblies- Size :152,834,048 (150 Mb ~)

I guess these leaked dynamic assemblies accounting for 150 Mb of space. Not sure whether 3 Gb of Native memory is due to these assemblies ?

More digging around with this assemblies :

!dumpdomain give me large Unknown dynamic assemblies as below :

Assembly:           000000000fa9d0d0 (Dynamic) []
ClassLoader:        0000000002be1d40
SecurityDescriptor: 000000000fc08a00
  Module Name
000007fe96d38e68            Dynamic Module

and  !EEHeap -loader gives same number of 0 sized modules : 
Module 000007fea0b7b758: Size: 0x0 (0) bytes.
Module 000007fea0b7c1e8: Size: 0x0 (0) bytes.
Module 000007fea0b7cc78: Size: 0x0 (0) bytes.

Checked for blocked GC Finalizer thread it is not the case, from below stack trace. It is waiting for Finalization event to occur.

0:000> ~20 k
Child-SP          RetAddr           Call Site
00000000`0eedf3b8 000007fe`fd6f1430 ntdll!ZwWaitForMultipleObjects+0xa
00000000`0eedf3c0 00000000`77501723 KERNELBASE!WaitForMultipleObjectsEx+0xe8
00000000`0eedf4c0 000007fe`f60939d4 kernel32!WaitForMultipleObjectsExImplementation+0xb3
00000000`0eedf550 000007fe`f6094799 clr!SVR::WaitForFinalizerEvent+0xcc
00000000`0eedf590 000007fe`f5f0458c clr!SVR::GCHeap::FinalizerThreadWorker+0x4a
00000000`0eedf5d0 000007fe`f5f0451a clr!Frame::Pop+0x50

Dump has the same number of System.Reflection.Emit.InternalModuleBuilder and System.Reflection.Emit.InternalAssemblyBuilder objects as that of leaked dynamic assemblies.

I noticed System.Reflection.Emit.DynamicResolver in Top finalizer queue and dumped all of them and correlated these to dynamic assembly address as follows.

Dumped around 5 DynamicResolver objects and tracked DynamicResolver -> m_method -> m_module (00000001801728a0)

00000001801728a0 this is the address of one module from list of InternalModuleBuilder list. Most of them was pointing to same module.

0:000> !dumpheap -type System.Reflection.Emit.DynamicResolver
         Address               MT     Size
000000018017d5a8 000007fef4c7c8b0       72     
000000018018d5b0 000007fef4c7c8b0       72     
00000001801931b0 000007fef4c7c8b0       72     
------- and on


0:000> !do 000000018017d5a8
Name:        System.Reflection.Emit.DynamicResolver
MethodTable: 000007fef4c7c8b0
EEClass:     000007fef4754300
Size:        72(0x48) 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
000007fef4c44458  4002aaa        8      System.Object[]  0 instance 0000000000000000 m_exceptions
000007fef4c9a690  4002aab       10        System.Byte[]  0 instance 0000000000000000 m_exceptionHeader
000007fef4ca20c0  4002aac       18 ...mit.DynamicMethod  0 instance 0000000180172690 m_method
000007fef4c9a690  4002aad       20        System.Byte[]  0 instance 000000018017d5f0 m_code
000007fef4c9a690  4002aae       28        System.Byte[]  0 instance 000000018017d650 m_localSignature
000007fef4c992b8  4002aaf       38         System.Int32  1 instance                3 m_stackSize
000007fef4c7c788  4002ab0       30 ...Emit.DynamicScope  0 instance 0000000180172b80 m_scope

0:000> !do 0000000180172690 
Name:        System.Reflection.Emit.DynamicMethod
MethodTable: 000007fef4ca20c0
EEClass:     000007fef475e298
Size:        112(0x70) 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
000007fef4c44458  4002ac6        8      System.Object[]  0 instance 0000000180172700 m_parameterTypes
000007fef4cafa88  4002ac7       10 ...RuntimeMethodInfo  0 instance 000000018017d678 m_methodHandle
000007fef4c987f8  4002ac8       18   System.RuntimeType  0 instance 00000004800e7900 m_returnType
000007fef4c7c578  4002ac9       20 ...ynamicILGenerator  0 instance 0000000180172a30 m_ilGenerator
000007fef4c4eb18  4002aca       28 ...mit.DynamicILInfo  0 instance 0000000000000000 m_DynamicILInfo
000007fef4c97de0  4002acb       60       System.Boolean  1 instance                1 m_fInitLocals
000007fef4c9f1d8  4002acc       30 ...ion.RuntimeModule  0 instance 00000001801728a0 m_module
000007fef4c97de0  4002acd       61       System.Boolean  1 instance                0 m_skipVisibility
000007fef4c987f8  4002ace       38   System.RuntimeType  0 instance 0000000000000000 m_typeOwner
000007fef4c7c330  4002acf       40 ...d+RTDynamicMethod  0 instance 00000001801729d8 m_dynMethod
000007fef4c7c8b0  4002ad0       48 ...t.DynamicResolver  0 instance 000000018017d5a8 m_resolver
000007fef4c97de0  4002ad1       62       System.Boolean  1 instance                0 m_profileAPICheck
000007fef4c99d18  4002ad2       50 ...n.RuntimeAssembly  0 instance 0000000000000000 m_creatorAssembly
000007fef4c97de0  4002ad3       63       System.Boolean  1 instance                1 m_restrictedSkipVisibility
000007fef4c88d70  4002ad4       58 ...g.CompressedStack  0 instance 00000001801729b0 m_creationContext
000007fef4c88020  4002ad5     16b8 ...rnalModuleBuilder  0   shared           static s_anonymouslyHostedDynamicMethodsModule
                                 >> Domain:Value  0000000002b66ba0:NotInit  0000000002c24a90:00000001801728a0 <<
000007fef4c96ae8  4002ad6     16c0        System.Object  0   shared           static s_anonymouslyHostedDynamicMethodsModuleLock
                                 >> Domain:Value  0000000002b66ba0:NotInit  0000000002c24a90:0000000180172798 <<


Opened log file 'C:\debug\new_dynamic_asm.log'
0:000> !dumpheap -type System.Reflection.Emit.InternalModuleBuilder
         Address               MT     Size
00000001800fe918 000007fef4c88020       64     
00000001801728a0 000007fef4c88020       64     
000000018017fa88 000007fef4c88020       64     
00000001801bee20 000007fef4c88020       64  
------- and on

I am not that handy with WinDbg, can somebody give me some clues.

1. How to relate above dynamic modules to reach out to buggy code. I believe this is due to Linq or Lambda expression.
2. As per report, size of Dynamic assemblies is 150 Mb, Is 3 Gb leak will be any different or dynamic modules might be linking to some native memory.

!heap -l gave me 188722 potential unreachable blocks were detected.

Native heap statistics using WinDbg PyKd plugin gave me below stats of native heap.

Notice the values rolling around 18,000

Statistics:

                                         Type name       Count  Size

                                    clr!RecordPool      817335  Unknown

                                       clr!RegMeta      272445  Unknown

                                 clr!CBlobPoolHash       36326  Unknown

                                  clr!MDInternalRW       36326  Unknown

                                   clr!StgBlobPool       36326  Unknown

                                       clr!CCeeGen       36298  Unknown

                                    clr!PEAssembly       18267  Unknown

                    clr!AssemblySecurityDescriptor       18249  Unknown

                                clr!DomainAssembly       18249  Unknown

                      clr!SharedSecurityDescriptor       18236  Unknown

                               clr!CStringPoolHash       18163  Unknown

                                     clr!CMiniMdRW       18163  Unknown

                                   clr!StgGuidPool       18163  Unknown

                                 clr!StgStringPool       18163  Unknown

                                 clr!CCustAttrHash       18163  Unknown

                                 clr!CGuidPoolHash       18163  Unknown

                                  clr!PESectionMan       18149  Unknown

                              clr!CeeSectionString       18149  Unknown

                                     clr!PESection       18149  Unknown

                           nativerd!CONFIG_ELEMENT        4932  Unknown

                          nativerd!ATTRIBUTE_VALUE        3912  Unknown

                         nativerd!SCHEMA_ATTRIBUTE        1473  Unknown

                                 clr!CAssemblyName        1116  Unknown

                     nativerd!COLLECTION_KEY_ENTRY         919  Unknown

                           nativerd!SCHEMA_ELEMENT         766  Unknown

                      clr!AssemblyMDInternalImport         720  Unknown

                           nativerd!CONFIG_SECTION         652  Unknown

                        nativerd!CONFIG_COLLECTION         570  Unknown

                 clr!ListNode<CHashNode * __ptr64>         444  Unknown

Belford

It seems that something in your application generate new assemblies. Are you using System.Reflection.Emit ? Could you run lmv (List Module Verbose) command. It should list all your 18k modules with additional information. Maybe these information will be usefull to understand why your application generate new assemblies. – Fatalism

Another thing you can try is to use DebugDiag collection and set a breakpoint on mscorlib.dll!System.AppDomain.DefineDynamicAssembly and log the stack trace. It may help you finding who is generated these assemblies. – Fatalism

Our code directly does not refer System.Reflection.Emit, not sure about 3rd party libraries. Command lmv surely gives lot of information. lm was only showing dtagent.dll lmv showed it was DynaTrace Agent, which is profiling software used by our apphosting. This might be resulting in this leak, needs to confirm. – Belford

I don't have access to server to put a breakpoint using debugdiag, will try if I get this done some how. Thanks – Belford

Also I don't see 18k assemblies with lmv command. – Belford

I don't know DynaTrace. Have you added DynaTrace to understand the memory leak ? Do you have a dump without it ? – Fatalism

DT shouldn't be creating dynamic assemblies - profilers use an API for instrumentation, they don't wrap existing assemblies for interception. I would do what Cyril said and put a breakpoint on it, alternatively you could hook the "AssemblyLoad" event (assuming it occurs in the same appdomain) and capture them that way. The breakpoint is going to be more accurate, more than likely. – Ow

I did not receive any more information from Application hosting team. Eventually we have migrated to Windows Server 2012. That might have fixed the issue. I am no longer actively troubleshooting this issue. Thanks for your help. – Belford

Check your 3rd party DLL's if anything in there is creating things dynamically. I ran into a memleak like this once while using Castle Dynamix proxy objects the wrong way. – Darwen

Check your code if everything is correctly disposed, all exceptions catched (even around using) and all references are released. Pls attach the code where you use these assemblies. – Piccard

"Assemblies" are not necessarily DLLs, so they won't be listed by lm. – Uterus

AFAIK, assemblies can only be unloaded together with an application domain. They will not be garbage collected. – Uterus

You didn't mention if your applicaiton was compiled with debug = true or not. You can determine this by running !FindDebugTrue (although hopfully you've resolved this already) – Moorefield

If you can get your hand Ants Memory profiler, it should help a lot. – Arel

Are you using IoC container/Dependency Injection in your WCF app? – Peccadillo

@CyrilDurand - lmv will not show you dynamic assemblies since they are not written to disk. – Catchascatchcan

Answer 1

WCF automatically generates serialization classes in memory for some communication protocols, mostly for XML communication, and seems to create a different class for each possible variation in the message structure; this easily explains the number of assemblies. This behavior is apparently normal for XML-based WCF protocols. If you have control over the protocol, switching to a non-XML communication protocol may resolve this problem.

The 3GB memory consumption is reasonable for this - the dynamic assembly will exist in both MSIL (.NET assembler language) and native versions in memory. The 150MB is probably for the MSIL version that was initially generated by WCF, and does not include the native code that gets generated by the .NET JIT compiler as soon as the MSIL version is "loaded" as a module and made callable.

The 17.45GB virtual space is not real memory, but instead is the distance between the lowest and highest memory locations where those modules get loaded; for example, if the main module loads at offset 0, and the first dynamic assembly loads at 00000000:0b000000, the total listed virtual memory will be about 185MB, even if the main module only takes 2MB and the dynamic assembly takes another 2MB. This is an exaggerated example, since they are usually packed in fairly well, but 1MB is typical between addresses, so 18000 * 1MB = 18000MB, which divided by 1024 gives exactly 17GB of address space (add another half GB for the rest of your system and you have the full virtual address space).

I have also seen one more type of fast-growing memory leak with WCF: if any part of a message is held by a persistent component of the application, the underlying XML COM object will not be garbage-collected, resulting in fairly large amounts of memory leaking. The .NET XML DOM uses the Windows COM XML subsystem, which is native code, and allocates on a native heap. This could explain the difference between managed and native memory heaps. Take a look at the actual memory in the dump (look for a tool that can filter out printable text), and check how much of it is formatted XML.

I have seen both of these leaks occur, and rapidly consume all of the memory on fairly large-scale servers, so I hope my experience provides an answer for you, or at least gives you some additional hints for tracing down your problem.

Brierwood

Answer 2

To diagnose what is using a large amount of memory, you want to use

!dumpheap -stat.

This will summarise the object usage by summing the number of instances. One area that hoards memory is the Large Object Heap (anything over 85k). This region will not be GC'd until absolutely necessary.

To look specifically at the LOH, you can use:

!dumpheap -stat -min 85000

For the items you are concerned with above, you need to find out what generation they are in. This can be done with finding the address of the item and then viewing the output of !DumpObject like so:

> 0:000> !do 0x0000000011b47450 
Name: System.Byte[]
MethodTable: 000007fef7d2e798
EEClass: 000007fef7932670
Size: 131096(0x20018) bytes
GC Generation: 3  <--- ****** Gen 3 == LOH
Array: Rank 1, Number of elements 131072, Type Byte
Element Type: System.Byte
Fields:
None

If it is Gen 3 in your example, you will need to look into what data structure it is. 85k+ continuous is usually byte[] or strings.

Shantay

Answer 3

We have seen issues with treading and NOT using thread safe collections in the code. Since most people like to read data into collections this seems to be a "repeated" issue with treading and such.

See a list of thread safe collections here: Thread Safe Collections

One more thing to add. We use RedGate/ANTS profiler. Also check your connection mgmt and cleanup of the WCF Service code.

Anaglyph

Answer 4

It likely is to be some sort of lambda query not known at compile time.

You may have the developers take a look at adding Microsoft Azure's Application Insights to the website in question. Then you can find what page has the long running code on it so you can have them narrow down on the affected code.

https://azure.microsoft.com/en-us/documentation/articles/app-insights-start-monitoring-app-health-usage/

Casern

Answer 5

Just as a wild suggestion, I can tell you that buffered (default) WCF services eat a lot of extra memory. If you switched to streamed, you could get a huge memory saving.

See this article https://msdn.microsoft.com/en-us/library/ms731913(v=vs.110).aspx.

In one case my WCF service reduced memory usage by 512meg by switching to buffered.

Inadvisable