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
