If broken it is, fix it you should

Using the powers of the debugger to solve the problems of the world - and a bag of chips    by Tess Ferrandez, ASP.NET Escalation Engineer (Microsoft)

.NET Debugging Demos Lab 6: Memory Leak - Review

.NET Debugging Demos Lab 6: Memory Leak - Review

  • Comments 10

Since it took me so long to get Lab 6 out the door i'll post the review right away... After this we only have one memory leak lab to go before you have gone through the whole lab set.

Previous demos and setup instructions

If you are new to the debugging labs, here you can find information on how to set up the labs as well as links to the previous labs in the series.

Information and setup instructions
Lab 1: Hang
Lab 1: Hang - review
Lab 2: Crash
Lab 2: Crash - review
Lab 3: Memory
Lab 3: Memory - review
Lab 4: High CPU hang
Lab 4: High CPU hang - review
Lab 5: Crash
Lab 5: Crash - review
Lab 6: Memory leak

Problem description:

We have started getting out of memory exceptions on the buggy bits site and we have been able to determine a scenario in which we think we are leaking memory but we can't seem to figure out where the memory is going. 

The leak seems to be occurring on our ProductInfo page for example

http://localhost/BuggyBits/ProductInfo.aspx?ProductName=Bugspray

and we can reproduce it by stress testing.  

It seems like it is leaking just a small bit every time but since it is something that customers look at a lot and over time the process will crash with an out of memory exception.  

Any help is greatly appreciated!

Reproduce the issue and gather data:

1. Restart IIS (iisreset)

2. Browse to http://localhost/BuggyBits/ProductInfo.aspx?ProductName=Bugspray

3. Set up performance monitoring per Lab 3 but also add the .NET CLR Loading counters and start monitoring the performance

4. Stress the application with tinyget (tinyget -srv:localhost -uri:/BuggyBits/ProductInfo.aspx?ProductName=Bugspray -threads:50 -loop:20)

5. After tinyget has finished, get a hangdump with adplus (adplus -hang -pn w3wp.exe -quiet)

6. Stop the performance monitor log

Review the performance monitor log to figure out what we are leaking:

1. Open up the performance monitor log in performance monitor and look at the following counters (set the scale appropriately so that you can see the graphs in the window)

Process\Private Bytes
Process\Virtual Bytes
.NET CLR Memory\# Bytes in all heaps
.NET CLR Memory\# Total committed bytes
.NET CLR Memory\# Total reserved bytes
.NET CLR Loading\Current Assemblies

Note: The scale for virtual bytes is different than private bytes and #Bytes in all Heaps in order for it to fit in the window

2. Compare Private Bytes, Virtual Bytes and #Bytes in all heaps

Q: Do the graphs for these 3 counters follow eachother or do they diverge? Based on this, can you tell if the issue we are facing is a virtual bytes leak, a native leak or a .NET leak?

A: The graphs for private bytes and virtual bytes seem to follow eachother so it doesnt seem like we are leaking virtual memory (reserving without committing).  The graphs for private bytes and #Bytes in all heaps follow eachother for a while and then private bytes continue growning but #Bytes in all heap stay flat (or even go down) so it looks like we might have a native leak. 

3. Look at the Current Assemblies counter

Q: Should this counter stay flat or is it ok for this counter to increase like this? What does it mean?

A: The current assemblies counter tells us how many .net assemblies are loaded in the process.  Typically you would see this go up at the beginning of a process or right after an application/appdomain restart since assemblies are loaded at that point.  After this it should stay relatively flat.  In this case it is constantly increasing which means that we keep loading up new assemblies during the lifetime of the process, and at a pretty steady rate.  Since assemblies can not be unloaded unless the application domain is unloaded the memory used for loading these assemblies will not be returned.

Debug the memory dump

If the curves for private bytes and bytes in all heaps diverge we either have a "native leak" which means that we have a native component that is leaking (in which case debug diag would be the next step), or we have an assembly leak.

1. Open the memory dump, load up the symbols and load sos.dll (see information and setup instructions for more info)

Q: What is the size of the memory dump (on disk)

A: In my case the dump was ~220 MB. 

2. Run !eeheap -gc and !dumpheap -stat

0:000> !eeheap -gc
Number of GC Heaps: 2
------------------------------
Heap 0 (001a9dd0)
generation 0 starts at 0x032786bc
generation 1 starts at 0x03002144
generation 2 starts at 0x02eb0038
ephemeral segment allocation context: none
 segment    begin allocated     size            reserved
001bef48 7a733370  7a754b98 0x00021828(137,256) 00005000
001aff58 790d8620  790f7d8c 0x0001f76c(128,876) 00005000
02eb0000 02eb0038  03bd5ac0 0x00d25a88(13,785,736) 02cbf000
Large object heap starts at 0x0aeb0038
 segment    begin allocated     size            reserved
0aeb0000 0aeb0038  0aec2b48 0x00012b10(76,560) 01fdf000
Heap Size  0xd7952c(14,128,428)
------------------------------
Heap 1 (001aade8)
generation 0 starts at 0x071f87a4
generation 1 starts at 0x06fced10
generation 2 starts at 0x06eb0038
ephemeral segment allocation context: none
 segment    begin allocated     size            reserved
06eb0000 06eb0038  07d0d0a8 0x00e5d070(15,061,104) 02dcf000
Large object heap starts at 0x0ceb0038
 segment    begin allocated     size            reserved
0ceb0000 0ceb0038  0ceb0048 0x00000010(16) 01fff000
Heap Size  0xe5d080(15,061,120)
------------------------------
GC Heap Size  0x1bd65ac(29,189,548)

0:000> !dumpheap -stat
...
79109778      1,578        88,368 System.Reflection.RuntimeMethodInfo
7912d7c0        481       103,472 System.Int32[]
79104368      6,313       151,512 System.Collections.ArrayList
79101fe4      3,276       183,456 System.Collections.Hashtable
7912d9bc      3,385       620,736 System.Collections.Hashtable+bucket[]
7912d8f8     15,018       682,392 System.Object[]
7912dd40      5,628       865,032 System.Char[]
7912dae8      2,005       985,856 System.Byte[]
790fd8c4     38,507     7,514,016 System.String
001a96d8        176    15,583,404      Free
Total 149,732 objects, Total size: 29,036,468 

Q: What is the size of the .NET heap according to !eeheap -gc, why is it different from #Bytes in all heaps?

A: Bytes in all heaps does not include the Free objects

We saw from performance monitor that we appeared to be leaking assemblies, so the next step is to determine where these assemblies are created and why we are leaking them.

3. Run !dumpdomain to look at the assemblies loaded in the process

 

0:000> !dumpdomain 
...
--------------------------------------
Domain 2: 001cca58
LowFrequencyHeap: 001cca7c
HighFrequencyHeap: 001ccad4
StubHeap: 001ccb2c
Stage: OPEN
SecurityDescriptor: 001cf910
Name: /LM/W3SVC/1/Root/BuggyBits-1-128502167929266605
Assembly: 001b0b20 [C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll]
ClassLoader: 00171e60
SecurityDescriptor: 642aca07
  Module Name
790c2000 C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll
0260239c C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\sortkey.nlp
02602010 C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\sorttbls.nlp

Assembly: 001bdee8 [C:\WINDOWS\assembly\GAC_32\System.Web\2.0.0.0__b03f5f7f11d50a3a\System.Web.dll]
ClassLoader: 001bdce8
SecurityDescriptor: 642aca07
  Module Name
6638c000 C:\WINDOWS\assembly\GAC_32\System.Web\2.0.0.0__b03f5f7f11d50a3a\System.Web.dll

...

Assembly: 12346190 [uaavec2w, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null]
ClassLoader: 0f4db540
SecurityDescriptor: 642aca07
  Module Name
11b7de00 uaavec2w, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null

Assembly: 15876720 [80uti-fi, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null]
ClassLoader: 158767a8
SecurityDescriptor: 642aca07
  Module Name
11b7e380 80uti-fi, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null

Assembly: 158770d0 [gyq9ceq2, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null]
ClassLoader: 15877158
SecurityDescriptor: 642aca07
  Module Name
11b7e900 gyq9ceq2, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null

Q: Which domain has most assemblies loaded?

A: Most of them appear to be loaded in the BuggyBits application domain

Q: Are these dynamic assemblies or assemblies loaded from disk? (is there a path associated with them)

A: Only a few (System.Web.dll etc.) have paths associated with them, the rest don't which means that they are dynamically generated assemblies.

4. Dump the module contents using  !dumpmodule <moduleaddress> where module address is the address given right after Module Name on one or a few of the dynamic assemblies. eg. in the example below you would run !dumpmodule 11b7e900

Module Name
11b7e900 gyq9ceq2, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null

5. Run dc <MetaDataStart> <MetaDataEnd>  to dump out the metadata for the module and find out what is implemented in this dynamic assembly. eg. in the example below you would run dc 114d09e4 114d09e4+0n4184    
Note:  We use the start address + 0n4184 because the metadata is 4148 bytes and the 0n stands for decimal  

0:000> !dumpmodule 11b7e900
Name: gyq9ceq2, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null
Attributes: PEFile
Assembly: 158770d0
LoaderHeap: 00000000
TypeDefToMethodTableMap: 16e2a2c4
TypeRefToMethodTableMap: 16e2a2dc
MethodDefToDescMap: 16e2a33c
FieldDefToDescMap: 16e2a3a8
MemberRefToDescMap: 16e2a3d4
FileReferencesMap: 16e2a4c4
AssemblyReferencesMap: 16e2a4c8
MetaData start address: 114d09e4 (4184 bytes)

0:000> dc 114d09e4 114d09e4+0n4184
...
114d0fc4  00000000 6f4d3c00 656c7564 7967003e  ......gy
114d0fd4  65633971 642e3271 58006c6c 65536c6d  q9ceq2.dll.XmlSe
114d0fe4  6c616972 74617a69 576e6f69 65746972  rializationWrite
114d0ff4  6f725072 74637564 63694d00 6f736f72  rProduct.Microso
114d1004  582e7466 532e6c6d 61697265 617a696c  ft.Xml.Serializa
114d1014  6e6f6974 6e65472e 74617265 73416465  tion.GeneratedAs
114d1024  626d6573 5800796c 65536c6d 6c616972  sembly.XmlSerial
114d1034  74617a69 526e6f69 65646165 6f725072  izationReaderPro
114d1044  74637564 6c6d5800 69726553 7a696c61  duct.XmlSerializ
114d1054  00317265 646f7250 53746375 61697265  er1.ProductSeria
114d1064  657a696c 6d580072 7265536c 696c6169  lizer.XmlSeriali
114d1074  4372657a 72746e6f 00746361 74737953  zerContract.Syst
114d1084  582e6d65 53006c6d 65747379 6d582e6d  em.Xml.System.Xm
114d1094  65532e6c 6c616972 74617a69 006e6f69  l.Serialization.
114d10a4  536c6d58 61697265 617a696c 6e6f6974  XmlSerialization
114d10b4  74697257 58007265 65536c6d 6c616972  Writer.XmlSerial
114d10c4  74617a69 526e6f69 65646165 6d580072  izationReader.Xm
114d10d4  7265536c 696c6169 0072657a 536c6d58  lSerializer.XmlS
114d10e4  61697265 657a696c 706d4972 656d656c  erializerImpleme
114d10f4  7461746e 006e6f69 74697257 505f3465  ntation.Write4_P
114d1104  75646f72 41007463 435f7070 2e65646f  roduct.App_Code.
114d1114  71726778 3774726d 6f725000 74637564  xgrqmrt7.Product
114d1124  69725700 5f336574 646f7250 00746375  .Write3_Product.
114d1134  70696853 676e6970 6f666e49 69725700  ShippingInfo.Wri
114d1144  5f326574 70696853 676e6970 6f666e49  te2_ShippingInfo
114d1154  696e4900 6c614374 6361626c 2e00736b  .InitCallbacks..
...

Q: What type of assembly was this?  What is it used for? How is it generated?

A: This is an XmlSerialization assembly.  It contains automatically generated code for serializing and deserializing a certain type (in this case the type is Product).  This type of assembly is generated when you create a new XmlSerializer in code.  Internally it is also used when passing arguments or return values from and to webservices.

Putting it all together and determining the cause of the assembly leak

If we look at the MSDN documentation for XmlSerializer we get the following information about dynamically generated assemblies related to XmlSerialization:

Dynamically Generated Assemblies

To increase performance, the XML serialization infrastructure dynamically generates assemblies to serialize and deserialize specified types. The infrastructure finds and reuses those assemblies. This behavior occurs only when using the following constructors:

XmlSerializer..::.XmlSerializer(Type)
XmlSerializer..::.XmlSerializer(Type, String)

If you use any of the other constructors, multiple versions of the same assembly are generated and never unloaded, which results in a memory leak and poor performance. The easiest solution is to use one of the previously mentioned two constructors. Otherwise, you must cache the assemblies in a Hashtable...

From this, and the fact that our performance logs and dump shows that we are continously generating new XML serialization assemblies we can conclude that it is very likely that we are not using one of the standard constructors.  Search the project code for new XmlSerializer or use reflector like in this example to determine where we are generating these dynamic assemblies.

Q: What method / line of code is causing the problem?

A:  This line in DataLayer.GetProductInfo is causing the problem

XmlSerializer xs = new XmlSerializer(typeof(Product), extraTypes);

Resolve the issue and rerun the test to verify the solution

1. Resolve the issue by caching the XmlSerializer using the sample in the MSDN documentation for XmlSerializer.

2. Rerun the test to verify that the assembly "leak" no longer exists.

 

Have fun,

Tess 

  • About MSN (Live), the big mistake sitemap.xml

    Sitemap 0.90 in the Microsoft support at the same time, Microsoft has put a big mistake, unable to submit such as:

    Www.example_example.com

    Www.example-example.com,

    Www.example.com and www.example.example.com only to the website, such as the example-example.com I will always be “The web address isn’t valid.” Block from the webmaster.live.com the.

  • not sure i follow...

  • Tess -

     How did you think to look at Assemblies in PerfMon?  Do you have a set of PerfMon counters that you *always* typically look at for memory leaks?

     For our ASP.NET sites, we are periodically dumping the following:

    .Net CLR Exceptions(*)

    .Net CLR Memory(*)

    ASP.Net Apps v2.0.50727(*)

    ASP.Net v2.0.50727\Worker Process Restarts

    Memory\Available Bytes

    Would you recommend always dumping .Net CLR Assembly stats also?

  • if it is a memory leak or increasing memory usage and I can rule out .net objects the option is either a native memory leak or a .net loader memory leak.  

    When I have ruled out managed memory as the highest bidder I look at the assemblies, it is a pretty quick check and it saves me from doing leaktracking with debugdiag but debug diag would also have shown the same thing, i.e. that most of the allocations were on the .net loader heap.

    Since .net loader heaps are fairly frequent i usually include all .net counters in the perfmon logs (including .net clr loading).  They don't contain too many data points so there is minimal or no impact on the system to listen for them.

  • We have a similar problem to this demo.  The modules have metadata as shown below.  It looks like some sort of XSL transform generated assembly?

    Has anyone else had this problem?

    ....K........<Mo

    dule>.JScript 0.

    Script3.System.X

    ml.Xsl.CompiledQ

    uery.Microsoft.J

    Script.mscorlib.

    GlobalScope.Comp

    ilerGlobalScopeA

    ttribute.System.

    Runtime.Compiler

    Services.ScriptO

    bject.VsaEngine.

    Microsoft.JScrip

    t.Vsa.Import.Pac

    kage.INeedEngine

    .Object.System.L

    ateBinding.Equal

    ity.NumericBinar

    y.Convert.Int32.

    GlobalObject.Act

    iveXObjectConstr

    uctor.Boolean.Ru

    ntimeTypeHandle.

    SecurityTranspar

    entAttribute.Sys

    tem.Security.Ref

    erenceAttribute.

    .ctor.Global Cod

    e..cctor..init.s

    afeUri.base.uri.

    GetEngine.SetEng

    ine.vsa Engine.e

    ngine.JScriptImp

    ort.JScriptPacka

    ge.ToObject.obj.

    Call.EvaluateEqu

    ality.GetNonMiss

    ingValue.Evaluat

    eNumericBinary.g

    et_ActiveXObject

    .CreateInstance.

    SetValue.CreateE

    ngineWithType.iw

    a17tsd.JScript M

    odule.....S.y.s.

    t.e.m..%S.y.s.t.

    e.m...C.o.l.l.e.

    c.t.i.o.n.s...S.

    y.s.t.e.m...T.e.

    x.t..=S.y.s.t.e.

    m...T.e.x.t...R.

    e.g.u.l.a.r.E.x.

    p.r.e.s.s.i.o.n.

    s...S.y.s.t.e.m.

    ..X.m.l...S.y.s.

    t.e.m...X.m.l...

    X.s.l..!S.y.s.t.

    e.m...X.m.l...X.

    P.a.t.h...s.u.b.

    s.t.r...i.n.d.e.

    x.O.f...c.h.a.r.

    A.t...l.e.n.g.t.

    h...c.o.n.c.a.t.

    ..a.s.y.n.c...l.

    o.a.d...p.a.r.s.

    e.E.r.r.o.r...e.

    r.r.o.r.C.o.d.e.

    .././...:.../..-

    M.s.x.m.l.2...D.

    O.M.D.o.c.u.m.e.

    n.t...4...0.....

    .).....E...|...D

    ...?_....:..z\V.

    4... ..... .....

    .. ... ..... ...

    . ......... ....

    .......... ....

    .............. .

    ........ .......

    .=. ..... ......

    ...E...'......%.

    ).%.).%.).%.%.-.

    ).%.%.%.%.%.%.).

    ....R..MSystem.X

    ml, Version=2.0.

    0.0, Culture=neu

    tral, PublicKeyT

    oken=b77a5c56193

    4e089..N..ISyste

    m, Version=2.0.0

    .0, Culture=neut

    ral, PublicKeyTo

    ken=b77a5c561934

    e089..P..Kmscorl

    ib, Version=2.0.

    0.0, Culture=neu

    tral, PublicKeyT

    oken=b77a5c56193

    4e089....-..

  • Actually this is a pretty common issue.  It occurrs if you continously use the same XSLT transforms and the transforms use script blocks.  To avoid it you should cache the transform or use precompiled code snippets

    http://support.microsoft.com/?id=316775

  • Thanks for the help.  After your tip-off I tracked the problem to our content management system.

  • Hi Tess,

    We have a high memory situation in the stress testing of our ASP.NET application. We ran 2 tests of 5 hours duration. We start getting out of memory error within an hour in the second test. I captured the performance counters and found that in the first test Private Bytes, Virtual Bytes and the #Bytes in all heap are following each other. In the second test though the curves are what you described in this exercise. What is more interesting, there is a big drop of #Bytes in all heap in the begining of the second test but Private Bytes and Vitual Bytes stays high at their level. We do not recycle the worker process in between 2 tests. What can cause this? I ran debugdiag leak tracking but, it did not show anything leaking. It does not look like assembly leak also. What I see in the memory analysis by debugdiag there is 600 MB free memory.

    Virtual Memory Summary

    Size of largest free VM block   58.79 MBytes

    Free memory fragmentation   90.61%

    Free Memory   626.16 MBytes   (30.58% of Total Memory)

    Reserved Memory   196.57 MBytes   (9.60% of Total Memory)

    Committed Memory   1.20 GBytes   (59.83% of Total Memory)

    Total Memory   2.00 GBytes

    Largest free block at   0x00000000`6e016000

    Virtual Allocation Summary

    Reserved memory   135.18 MBytes

    Committed memory   1.01 GBytes

    Mapped memory   71.20 MBytes

    Reserved block count   443 blocks

    Committed block count   958 blocks

    Mapped block count   336 blocks

    Loaded Module Summary

    Number of Modules   221 Modules

    Total reserved memory   1.19 MBytes

    Total committed memory   148.86 MBytes

    I will greatly appreciate any suggestion you make to troubleshoot this problem.

    Thanks,

    -Himadri

  • himadric,

    THe free memory you see here is just unused VM bytes, in other words memory that has neither been reserved or committed...

    The big drop sounds like maybe an appdomain that has shut down, but it doesnt make sense that private bytes and virtual bytes would stay high in that case...  i would recommend capturing a memory dump at that time and checking out !eeheap -gc to see how much .net mem you are using and also !dumpheap -stat to see if you have a lot of "free" objects on the .net heaps

    Tess

  • Hi, I have lots of dynamic assemblies loaded, but the dumpmodule shows not metadata info:

    Assembly: 000000003ed53058 (Dynamic) []

    ClassLoader: 000000003ed530c8

    SecurityDescriptor: 000000003ec55ee0

     Module Name

    0000000015838b98 Dynamic Module

    How can I explore the module contents?

Page 1 of 1 (10 items)
Leave a Comment
  • Please add 8 and 5 and type the answer here:
  • Post