I was reading this post about spam ping-bots from OldNewThing and it makes me a bit mad because they just steal your content to make money, and create a lot of spam in my mailbox making it harder for me to find the real comments/track-backs.  What is even more messed up is that some of these sites ask you to sign in and some even have you pay for content that someone else (like me) wrote:) amazing... so anyways, if you read this from some place other than http://blogs.msdn.com/Tess, an RSS reader or a valid aggregate site like www.asp.net, technorati, msdn etc. etc.  (there are many valid ones too).  then read the post from the OldNewThing.

Anyways, on to the lab review... the original lab was posted here and my comments are in-line in red

(I had to cut out some of the contents of the original post here becuase this post got way too big:))

Examine the performance logs

...

4. Add the following counters (for the w3wp.exe process) using the + button or Ctrl+I

  • .NET CLR Memory/# Bytes in all Heaps
  • .NET CLR Memory/Large Object Heap Size
  • .NET CLR Memory/Gen 2 heap size
  • .NET CLR Memory/Gen 1 heap size
  • .NET CLR Memory/Gen 0 heap size
  • Process/Private Bytes
  • Process/Virtual Bytes

The counters should now show up at the bottom of the screen...

5. Right-click any of them and choose properties and on the Data tab set the scale for all of them to 0,0000001 to make sure you can view the whole graph on the screen

Note: If you click the lightbulb Ctrl+H the selected counter will be highlighted so that it is easier to distinguish which line corresponds to which counter

Q: What are the latest values for these counters?

Q: Compare the curves for Virtual Bytes, Private Bytes and #Bytes in all Heaps, do they follow eachother or do they diverge?

A: the curves for #Bytes in all heaps (bottom), Private bytes (middle) and virtual bytes (top) definitely follow eachother.  This means that the memory increase is definitenly caused by an increase in #Bytes in all heaps (.net GC memory). 

To identify what type of "leak" we have we can use this rule-of-thumb

a. virtual bytes jump, private bytes stay flat => a virtual byte leak i.e. some component is reserving memory but not using it => use debug diag to track it down
b. private bytes jump but #Bytes in all heaps stay flat => native or loader heap leak. => use debug diag to track it down and/or check if the number of assemblies increase (counter under .net clr loading)
c. #Bytes in all heaps and private bytes follow eachother => investigate the .net GC heaps

There is about a 200-300 MB difference between virtual bytes and private bytes, this is completely normal in a server process, especially in a .net process since a lot of memory gets reserved initially for the GC heaps (and other things like dlls etc.).  It is also normal to see this pattern in virtual bytes where it jumps in chunks and that is because heaps (and other mem) are typically reserved in chunks.

Q: Can you tell from this if it appears to be a native "leak", a .net memory "leak" or a leak on the loader heap (dynamic assemblies)?

A: Per the above, it looks like a .net GC memory issue.

Q: At the end the log (after you finish your tinyget run) does memory stay flat or does it go down?

A: It stays flat so it doesn't appear that memory is reclaimed even after the stress test is done.

6. Add the counters for .NET CLR Memory/# Gen 0 Collections, .NET CLR Memory/# Gen 1 Collections, .NET CLR Memory/# Gen 2 Collections

Q: Do any collections occurr after the tinyget run is done? if not, why not?

A: I have mentioned this a number of times before (like in the GC pop-quiz) but it's worth mentioning again, garbage collections only occurrs on allocations or when you manually call GC.Collect().  After our stress run is done we don't do neither so no-one will collect the memory until its needed.  

7. Open task manager and under "View/Select Columns..." add the column "Virtual Memory Size". Compare the values for Mem Usage and VM Size to the values for Private Bytes and Virtual Bytes in perfmon. (Note: since they are given in K in task manager you need to multiply these values by 1024).

Q: What does Mem Usage show?

Q: What does VM Size show?

A: In my case taskmanager showed ~746 MB for both of these and then Mem Usage jumped up to ~864 MB when I grabbed the memory dump.  What is important here is to realize what these values are...

From the task manager helpfiles we have the following info about these columns

Performance monitor has these explanations about the counters we added

Private Bytes "the current size, in bytes, of memory that this process has allocated that cannot be shared with other processes."
Virtual Bytes "the current size, in bytes, of the virtual address space the process is using. Use of virtual address space does not necessarily imply corresponding use of either disk or main memory pages. Virtual space is finite, and the process can limit its ability to load libraries."
Working Set "the current size, in bytes, of the Working Set of this process. The Working Set is the set of memory pages touched recently by the threads in the process. If free memory in the computer is above a threshold, pages are left in the Working Set of a process even if they are not in use. When free memory falls below a threshold, pages are trimmed from Working Sets. If they are needed they will then be soft-faulted back into the Working Set before leaving main memory."
#Bytes in all heaps "This counter is the sum of four other counters; Gen 0 Heap Size; Gen 1 Heap Size; Gen 2 Heap Size and the Large Object Heap Size. This counter indicates the current memory allocated in bytes on the GC Heaps."
Gen 0 heap size "This counter displays the maximum bytes that can be allocated in generation 0 (Gen 0); its does not indicate the current number of bytes allocated in Gen 0. A Gen 0 GC is triggered when the allocations since the last GC exceed this size. The Gen 0 size is tuned by the Garbage Collector and can change during the execution of the application. At the end of a Gen 0 collection the size of the Gen 0 heap is infact 0 bytes; this counter displays the size (in bytes) of allocations that would trigger the next Gen 0 GC. This counter is updated at the end of a GC; its not updated on every allocation."
Gen 1 heap size "This counter displays the current number of bytes in generation 1 (Gen 1); this counter does not display the maximum size of Gen 1. Objects are not directly allocated in this generation; they are promoted from previous Gen 0 GCs. This counter is updated at the end of a GC; its not updated on every allocation."
Gen 2 heap size "This counter displays the current number of bytes in generation 2 (Gen 2). Objects are not directly allocated in this generation; they are promoted from Gen 1 during previous Gen 1 GCs. This counter is updated at the end of a GC; its not updated on every allocation."
LOH size "This counter displays the current size of the Large Object Heap in bytes. Objects greater than 20 KBytes 85000 bytes are treated as large objects by the Garbage Collector and are directly allocated in a special heap; they are not promoted through the generations. This counter is updated at the end of a GC; its not updated on every allocation."
 

A few things of note here...

1. Gen 0 heap size shows the budget for Gen 0, not the size of the objects in Gen 0.

2. Gen 0, 1, 2 and LOH counters are updated after each collection, not after each allocation.

3. The LOH explanation says that objects over 20 k are large objects, that used to be the case in 1.0 but has changed since then and since the counters are not version specific this hasn't been updated. For 1.1. and 2.0 it is 85000 bytes. 

4. The working set consists of the pages loaded in RAM that have been recently touched by the process, it really doesn't have anything to do with the private bytes of the process (which is what we usually look at when we look at the memory usage of the process), it may be more and it may be less than private bytes. For winforms apps (non-services) there is usually a big difference in the workingset when you minimize the apps since the pages are then trimmed from the working set.  For services (like ASP.NET that usually doesnt happen so private bytes and working sets tend to stay in the same range) 

Get a memory dump

1. Open a command prompt and move to the debuggers directory and type in "adplus -hang -pn w3wp.exe -quiet" and hit enter

Open the dump in windbg

1. Open the dump file in windbg (the .dmp file should be located in your debuggers directory under a folder labeled hang_mode and todays date and time.

2. Set up the symbol path and load sos (see the setup instructions for more info)

Q: How big is the dump? Look at the size in the file explorer.

A: 864 096 k

Q: How does this compare to Private Bytes, Virtual Bytes and # Bytes in all Heaps.

A: Pretty similar to the workingset from the looks of it.  In reality it's the private bytes plus a few other things, typically falls within about 100 MB max of the private bytes value.

Examine the memory to get an idea of where the memory is going

1. Run !address -summary (this will give you an overview of the memory usage) and familiarize yourself with the output. Hint: check the windbg help files for !address  

0:000> !address -summary
-------------------- Usage SUMMARY --------------------------
    TotSize (      KB)   Pct(Tots) Pct(Busy)   Usage
   373b7000 (  904924) : 21.58%    85.85%    : RegionUsageIsVAD
   bfa89000 ( 3140132) : 74.87%    00.00%    : RegionUsageFree
    76e6000 (  121752) : 02.90%    11.55%    : RegionUsageImage
     67c000 (    6640) : 00.16%    00.63%    : RegionUsageStack
          0 (       0) : 00.00%    00.00%    : RegionUsageTeb
    144a000 (   20776) : 00.50%    01.97%    : RegionUsageHeap
          0 (       0) : 00.00%    00.00%    : RegionUsagePageHeap
       1000 (       4) : 00.00%    00.00%    : RegionUsagePeb
       1000 (       4) : 00.00%    00.00%    : RegionUsageProcessParametrs
       2000 (       8) : 00.00%    00.00%    : RegionUsageEnvironmentBlock
       Tot: ffff0000 (4194240 KB) Busy: 40567000 (1054108 KB)

-------------------- Type SUMMARY --------------------------
    TotSize (      KB)   Pct(Tots)  Usage
   bfa89000 ( 3140132) : 74.87%   : 
    834e000 (  134456) : 03.21%   : MEM_IMAGE
     95a000 (    9576) : 00.23%   : MEM_MAPPED
   378bf000 (  910076) : 21.70%   : MEM_PRIVATE

-------------------- State SUMMARY --------------------------
    TotSize (      KB)   Pct(Tots)  Usage
   34bea000 (  864168) : 20.60%   : MEM_COMMIT
   bfa89000 ( 3140132) : 74.87%   : MEM_FREE
    b97d000 (  189940) : 04.53%   : MEM_RESERVE

Largest free region: Base 80010000 - Size 7fefa000 (2096104 KB)

There is a great deal of information here but all of it may not be so obvious, and believe me I get confused sometimes too here.  In either case, I just use this as a bit of a guide to figure out where I should be looking so I don't feel that it matters all that much if the details are fuzzy.

A few things worth noting about this screen...

The screen basically shows all memory used by the process split into different types.  1st it shows them by region type which tells you what type of allocation was made. The most common memory hoggers are VAD = Virtual Alloc, Image = dlls and executables, and Heap = heaps the process owns... you can find the description for all of them in the windbg help.

Then it goes on to list them by type (IMAGE, MAPPED or PRIVATE) and finally by whether the area is just reserved or also committed.

Tot: ffff0000 (4 194 240 kb) means that I have 4 GB virtual address space in total to play with for this app.  With 32 bits you can address 4 GB and typically you only get 2GB of those for your usermode mem so typically you should see 2 GB here rather than 4 GB.  On a 64-bit system however, running a 32-bit proc you will get the full 4GB to play with and that is what I have here.    

Busy: 40567000 (1 054 108 kb) is what we are currently using (have reserved)

MEM_PRIVATE is memory that is private (not shared with any process) and not mapped to a file.  This should not be confused with Private Bytes in perfmon which shows the private allocated/committed bytes. MEM_PRIVATE shows the reserved + committed bytes.  

MEM_COMMIT is memory that is committed (but not neccessarily private), this is probably the closest you will get to private bytes. 

MEM_RESERVE is memory that is reserved but not committed,  all committed memory is by definition reserved as well so if you are looking for all reserved bytes (the closest you will get to virtual bytes) you have to add up MEM_COMMIT and MEM_RESERVE which gets you the number shown in Busy: 

Q: Which values corresponds best to the following

    • Private Bytes A: MEM_COMMIT
    • Virtual Bytes  A: Busy

Q: Where is most of the memory going (which RegionType)?

A: In this case ~904 MB is reserved for VAD which is where .net objects fit in since the GC heaps are allocated with virtual allocs.

Q: What does Busy, Pct(Busy) and Pct(Tots) mean?

A: Pct(Tots) shows you how many percent of the total virtual address space you are using for this region type, and Pct(Busy) shows how much of the reserved memory is used for this region type.  Pct(Busy) is definitely the most interesting one in my opinion.

Q: What does MEM_IMAGE mean?

A: From the helpfile "Memory that is mapped from a file that is part of an executable image.", in other words, dlls and exes.

Q: Under what region does .net memory fit in and why?

A: under RegionUsageIsVAD (see above)

From perfmon we could see that #Bytes in all Heaps follows Private bytes very closely meaning that the increase in memory is mostly an increase in .NET memory.  In other words we are looking for an answer to why our .net GC heaps keep growing.

Examine the .NET GC Heaps

1. Run !eeheap -gc to examine the size of the .NET GC heaps

0:000> !eeheap -gc
Number of GC Heaps: 2
------------------------------
Heap 0 (001aa148)
generation 0 starts at 0x32f0639c
generation 1 starts at 0x32ae3754
generation 2 starts at 0x02eb0038
ephemeral segment allocation context: none
 segment    begin allocated     size
001bfe10 7a733370  7a754b98 0x00021828(137256)
001b0f10 790d8620  790f7d8c 0x0001f76c(128876)
02eb0000 02eb0038  06eacb28 0x03ffcaf0(67095280)
100b0000 100b0038  140a4a08 0x03ff49d0(67062224)
18180000 18180038  1c15c650 0x03fdc618(66962968)
20310000 20310038  242eb99c 0x03fdb964(66959716)
28310000 28310038  2c2f04cc 0x03fe0494(66978964)
31190000 31190038  33185ff4 0x01ff5fbc(33513404)
Large object heap starts at 0x0aeb0038
 segment    begin allocated     size
0aeb0000 0aeb0038  0aec0b28 0x00010af0(68336)
Heap Size  0x15fd1310(368907024)
------------------------------
Heap 1 (001ab108)
generation 0 starts at 0x36e665bc
generation 1 starts at 0x36a28044
generation 2 starts at 0x06eb0038
ephemeral segment allocation context: none
 segment    begin allocated     size
06eb0000 06eb0038  0aea58d4 0x03ff589c(67066012)
14180000 14180038  1817eda8 0x03ffed70(67104112)
1c310000 1c310038  202f0550 0x03fe0518(66979096)
24310000 24310038  28304ca8 0x03ff4c70(67062896)
2c310000 2c310038  2fd62a48 0x03a52a10(61155856)
35190000 35190038  372253f4 0x020953bc(34165692)
Large object heap starts at 0x0ceb0038
 segment    begin allocated     size
0ceb0000 0ceb0038  0ceb0048 0x00000010(16)
Heap Size  0x15ab1570(363533680)
------------------------------
GC Heap Size  0x2ba82880(732440704)

Q: How many heaps do you have? Why?

A: 2 heaps because we're running the Server GC on a dual-proc box. Check out the GC pop-quiz for more info on this    

Q: How much memory is stored on the .net GC heaps?  Compare to #Bytes in all Heaps

A: GC Heap Size 0x2ba82880(732 440 704) it's pretty close to bytes in all heaps in perfmon, the slight difference stems from that #Bytes in all heaps shows what the memory usage looked like after the last GC.

Q: How much memory is on the large object heap? Hint: add up the sizes for all the Large Object heap segments. Compare to Large Object Heap Size in perfmon. 

A: its very minimal so the LOH doesnt seem to be an issue. 68 336 + 16 bytes

2. Run !dumpheap -stat to dump out all .net objects in a statistical fashion (Note: you can run !help DumpHeap to get help for the !dumpheap command or check out this post, this post or this post)

Q: Looking at the 5-10 object types that use most memory, what do you think is leaking?

66424cf4       37        57276 System.Web.Caching.ExpiresEntry[]
663b0cdc     4001       192048 System.Web.SessionState.InProcSessionState
7912d8f8     3784       255028 System.Object[]
7912d9bc      820       273384 System.Collections.Hashtable+bucket[]
6639e4c0     4037       290664 System.Web.Caching.CacheEntry
0fe11cf4    36000       576000 Link
790fdc5c    36161       723220 System.Text.StringBuilder
001a90c0     1105      7413924      Free
790fd8c4    51311    721773112 System.String
Total 163943 objects

A: most of the memory is used up by strings which is not that unusual to see given how common strings are in any type of app, but ~721 MB definitely seems a bit weird, and
36000 Links (whatever they may be) also sound fishy, especially since there is about the same amount of stringbuilders present in the dump.

Q: What "size" does the size column show? I.e. what is included in this "size"?  Hint: see the post (!dumpheap -stat explained) for more info.

A: If we dump out a Link object with !do we will see that a Link object has a pointer to a stringbuilder (url) and a pointer to a string (name).  The size of the link object is shown as 16 bytes which basically just includes the pointers and some overhead (method table etc.)

If on the other hand you run !objsize on it, you will see that the size shows up as 20144 bytes.  This is the size including the member variables, i.e. the size of the Link object and everything it references.

What you see in !dumpheap is the 16 bytes per link.  It wouldnt be feasible to include the size of the member variables for a few different reasons.

1. it would take a long time to calculate
2. some objects (say A and B) may both point to object C, if you did !objsize on A and B they would both include the size for C so the size column would be very confusing since it wouldnt be exclusive.
3. in a case like this one with the Link the size for !objsize feels like the correct size since a Link contains a url and a name. However if you look at a web control which has a member var _parent and you run !objsize on the web control, this will include the size of the parent which is not neccesarily as obvious.

0:000> !do 371d44cc 
Name: Link
MethodTable: 0fe11cf4
EEClass: 0fde5824
Size: 16(0x10) bytes
 (C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\Temporary ASP.NET Files\buggybits\b27906cc\f5f91899\App_Code.wbwztx_4.dll)
Fields:
      MT    Field   Offset                 Type VT     Attr    Value Name
790fdc5c  4000006        4 ...ext.StringBuilder  0 instance 371d44dc url
790fd8c4  4000007        8        System.String  0 instance 02f13cd8 name

0:000> !objsize 371d44cc 
sizeof(371d44cc) =        20144 (      0x4eb0) bytes (Link)

3. Dump out stats for various size strings to find out if there is a pattern (this is a bit of trial and error so you have to try a few different sizes to figure out where the bulk of the strings are. 

Q: In what range (between what sizes) do most of the strings exist?

A: Between 20000 and 25000 bytes  

4. Dump out the strings in that range

!dumpheap -mt <string MT> -min 20000 -max 25000 

In this case most of them will even be the exact same size which is a clue to what is going on... 

0:000> !dumpheap -mt 790fd8c4 -min 20000 -max 25000
------------------------------
Heap 0
 Address       MT     Size
02f1412c 790fd8c4    20020     
02f2d96c 790fd8c4    20020     
02f327c4 790fd8c4    20020     
02f3761c 790fd8c4    20020     
02f3c474 790fd8c4    20020     
02f412cc 790fd8c4    20020     
02f46124 790fd8c4    20020     
02f4af7c 790fd8c4    20020     
02f4fdd4 790fd8c4    20020     
02f54c2c 790fd8c4    20020     
...

5. Dump out a few of them to find out what they contain

!do <address of string - first column in the !dumpheap -mt output>

0:000> !do 02f327c4 
...
String: http://blogs.msdn.com/Tess
...

Q: What do these strings contain?

A: looks like the links shown in the links.aspx page

6. Pick a few and find out where they are rooted (i.e. why they can't be collected)  Note: You may want to try a couple different ones.

!gcroot <address of string>

0:000> !gcroot 02f327c4 
Note: Roots found on stacks may be false positives. Run "!help gcroot" for
more info.
Scan Thread 16 OSTHread 1948
Scan Thread 20 OSTHread 1b94
Scan Thread 21 OSTHread 1924
Scan Thread 22 OSTHread 188c
Scan Thread 14 OSTHread 1120
Scan Thread 24 OSTHread 13f8
Finalizer queue:Root:02f327a0(Link)->
02f327b0(System.Text.StringBuilder)->
02f327c4(System.String)

Q: Where are they rooted?  Why?

A: The string is a member variable of a string builder which in turn is a member variable of a link object (the url) and the Link object is rooted in the Finalizer queue which meanst that it is ready for finalization and is just waiting to be finalized.

Examine the finalizer queue and the finalizer thread

1. Look at the finalizer queue

!finalizequeue

0:000> !finalizequeue
SyncBlocks to be cleaned up: 0
MTA Interfaces to be released: 0
STA Interfaces to be released: 0
----------------------------------
------------------------------
Heap 0
generation 0 has 221 finalizable objects (0f44a764->0f44aad8)
generation 1 has 0 finalizable objects (0f44a764->0f44a764)
generation 2 has 45 finalizable objects (0f44a6b0->0f44a764)
Ready for finalization 18009 objects (0f44aad8->0f45c43c)
------------------------------
Heap 1
generation 0 has 338 finalizable objects (0f45d840->0f45dd88)
generation 1 has 4 finalizable objects (0f45d830->0f45d840)
generation 2 has 36 finalizable objects (0f45d7a0->0f45d830)
Ready for finalization 17707 objects (0f45dd88->0f46f234)
Statistics:
      MT    Count    TotalSize Class Name
663a1fc8        1           12 System.Web.Configuration.ImpersonateTokenRef
79116758        1           20 Microsoft.Win32.SafeHandles.SafeTokenHandle
791037c0        1           20 Microsoft.Win32.SafeHandles.SafeFileMappingHandle
79103764        1           20 Microsoft.Win32.SafeHandles.SafeViewOfFileHandle
6639c104        1           20 System.Web.PerfInstanceDataHandle
663f6b5c        1           28 System.Web.Security.FileSecurityDescriptorWrapper
663a105c        1           32 System.Web.Compilation.CompilationMutex
7910b630        2           40 System.Security.Cryptography.SafeProvHandle
79112728        5          100 Microsoft.Win32.SafeHandles.SafeWaitHandle
790fe704        2          112 System.Threading.Thread
7910a5c4        2          120 System.Runtime.Remoting.Contexts
...

Q: What objects are listed in the finalizequeue output? Hint: run !help finalizequeue

A: All objects that have finalizers/destructors are registered with the finalizer queue so that the finalizer will run the destructor once the object is garbage collected unless finalization is supressed in the dispose method.

Q: How many objects are "ready for finalization"?  What does this mean?

A: Around 36000 in total, so these objects are garbage collected and ready to be finalized.  If ready for finalization shows anything above 0 there is a pretty good chance the finalizer is blocked which is why these objects stick around waiting to be finalized, and with them goes all the memory they reference.

2. Find the finalizerthread to determine what it is doing. Run !threads and look for the thread listed with (Finalizer)

3. Move to the finalizer thread and examine the managed and native callstack

~5s   (5 should be substituted with the id of the finalizer thread)
kb 2000
!clrstack

0:000> !threads
...
  20    2 1b94 001ac2c0   200b220 Enabled  00000000:00000000 001ccc80     0 MTA (Finalizer)
...

0:020> !clrstack
OS Thread Id: 0x1b94 (20)
ESP       EIP     
02a0f8fc 7d61cca8 [HelperMethodFrame: 02a0f8fc] System.Threading.Thread.SleepInternal(Int32)
02a0f950 0fe90ce8 Link.Finalize()
02a0fc1c 79fbcca7 [ContextTransitionFrame: 02a0fc1c] 
02a0fcec 79fbcca7 [GCFrame: 02a0fcec]

Q: What object is it finalizing?

A: Looks like it is running the finalizer for a Link object.

Q: What is it doing?  Why is this causing high memory usage?

A: The finalizer for the Link object is stuck in a sleep which means that the finalizer is blocked so nothing in the process can be finalized, thus all the objects waiting for finalization will continue to stay in memory until the finalizer is unblocked and they can be finalized.

Conclusion:

Performing any type of blocking operations in the finalizer is very dangerous since this causes no objects to be finalized. Apart from checking that you do not perform any blocking operations in the finalizer you should always strive to dispose/close all objects with finalizers/destructors so that you don't end up in this all too common situation.

Hope you found this useful... the next lab will be a high CPU in GC lab...

Laters

Tess