Identifying High CPU in GC (.NET) because of LOH – using Windbg

I am sure most of us are aware that one of the common reasons for High CPU usage .NET is because of, percentage time spent on GC is high. There are lot of write up about this. Tess has amazing blog post  on this specifically, which explains in detail how to identify the symptoms. But one thing that I want share was the experience I had ,where in i could identify the real call stack which was causing allocation on LOH by have a break-point on the CLR Garbage collector itself. I am going to assume that you are aware of CLR GC and LOH and basic debugging using windbg.

FYI the Perfmon counter like “% Time spent in GC”, “Large Object Heap size” can identify we have an issue with allocation in LOH. But this only indicates there is a problem in High allocations that’s causing  GC to work hard and in turn causing high CPU usage . But does not point where the exact problem is .If there is a large code base and all of sudden if there is an issue like this it is hard to pinpoint where the root cause of the problem.

I am going to walk through an example on a button click the code allocates objects on LOH and identify it using windbg.

using System;
usingSystem.Collections.Generic;
usingSystem.Linq;
usingSystem.Windows.Forms;

namespaceWindowsFormsApplication1
{
public partial classForm1: Form
{
publicList<byte[]> buffer = newList<byte[]>();

publicForm1()
{
InitializeComponent();
}

private voidButton1Click(objectsender, EventArgs e)
{
AllocateinLOH();
}

voidAllocateinLOH()
{
var b = new byte[85001];
b.ToList().ForEach(
(x) => x = new byte());

buffer.Add(new byte[85001]);
}

}
}

In the above code AllocateinLOH will cause the heap allocations to LOH because the size is more than 85000 bytes. The next step is to launch the application and attach it to the debugger. To figure out the cause I could have got multiple memory dumps  and checked at every call stack when GC was happening . That is the harder way and we could be spending lot of time on that.

To get to solve the problem i always like to approach from the bottom of the stack. I was certain there should be a function within the CLR / GC which should be doing this and I was certain it has to be within MSCORWKS.dll. The next step was examine symbols using “x” command and here is the output

0:000> x mscorwks!wks::gc_heap::*

000007fe`e90d1340 mscorwks!WKS::gc_heap::alloc_allocated = <no type information>
000007fe`e89fd380 mscorwks!WKS::gc_heap::limit_from_size = <no type information>
000007fe`e8907e20 mscorwks!WKS::gc_heap::fix_older_allocation_area = <no type information>
000007fe`e90d1310 mscorwks!WKS::gc_heap::max_free_space_items = <no type information>
000007fe`e90cba38 mscorwks!WKS::gc_heap::gc_low = <no type information>
000007fe`e8dae150 mscorwks!WKS::gc_heap::grow_brick_card_tables = <no type information>
000007fe`e8a12d40 mscorwks!WKS::gc_heap::fix_generation_bounds = <no type information>
000007fe`e8a13040 mscorwks!WKS::gc_heap::fix_large_allocation_area = <no type information>
000007fe`e8a2c680 mscorwks!WKS::gc_heap::allocate_large_object = <no type information>
000007fe`e90c0478 mscorwks!WKS::gc_heap::slow = <no type information>
000007fe`e8ed8ec0 mscorwks!WKS::gc_heap::c_promote_callback = <no type information>

The above results are only partial because it was not necessary to get all the methods. The command “x mscorwks!wks::gc_heap::*” causes the debugger to get all the functions that are within the mscorwks dll with class name gc_heap. I knew it is gc_heap because prior to this I issued the command “x mscorwks!*gc*”. Because we don’t have private symbols for mscorwks we cannot see the type information. But we don’t need that for our purpose. The public symbols has FPO information for us to have break-point.

Form the above result the method name should be “allocate_large_object”

The next step was to put a break-point on the method

bp mscorwks!wks::gc_heap::allocate_large_object “!CLRStack”

And then click button and here is the callstack output

0:004> g
OS Thread Id: 0xf6f4 (0)
Child-SP         RetAddr          Call Site
000000000027e000 000007ff00190684 WindowsFormsApplication1.Form1.AllocateinLOH()
000000000027e060 000007feeab00555 WindowsFormsApplication1.Form1.Button1Click(System.Object, System.EventArgs)
000000000027e090 000007feeb1f5873 System.Windows.Forms.Control.OnClick(System.EventArgs)
000000000027e0d0 000007feeb1aadf7 System.Windows.Forms.Button.OnMouseUp(System.Windows.Forms.MouseEventArgs)
000000000027e130 000007feeb702b7d System.Windows.Forms.Control.WmMouseUp(System.Windows.Forms.Message ByRef, System.Windows.Forms.MouseButtons, Int32)
000000000027e200 000007feeab49b5a System.Windows.Forms.Control.WndProc(System.Windows.Forms.Message ByRef)
000000000027e3b0 000007feeab49954 System.Windows.Forms.ButtonBase.WndProc(System.Windows.Forms.Message ByRef)
000000000027e430 000007feeab53aa6 System.Windows.Forms.Button.WndProc(System.Windows.Forms.Message ByRef)
000000000027e460 000007feeab53945 System.Windows.Forms.Control+ControlNativeWindow.WndProc(System.Windows.Forms.Message ByRef)
000000000027e4b0 000007feeab52244 System.Windows.Forms.NativeWindow.Callback(IntPtr, Int32, IntPtr, IntPtr)
000000000027e560 000007fee8aab07a DomainBoundILStubClass.IL_STUB(Int64, Int32, Int64, Int64)
000000000027e810 000007feeab6e883 DomainBoundILStubClass.IL_STUB(MSG ByRef)
000000000027e990 000007feeab6e0f8 System.Windows.Forms.Application+ComponentManager.System.Windows.Forms.

UnsafeNativeMethods.IMsoComponentManager.FPushMessageLoop(Int32, Int32, Int32)
000000000027ebe0 000007feeab6db65 System.Windows.Forms.Application+ThreadContext.RunMessageLoopInner(Int32, System.Windows.Forms.ApplicationContext)
000000000027ed30 000007ff00190171 System.Windows.Forms.Application+ThreadContext.RunMessageLoop(Int32, System.Windows.Forms.ApplicationContext)
000000000027ed90 000007fee8aad502 WindowsFormsApplication1.Program.Main()
mscorwks!WKS::gc_heap::allocate_large_object:
000007fe`e8a2c680 4053            push    rbx

Bingo now at the bottom of the stack we can see the “allocate_large_object” and on the top of the stack it is the managed code that we wrote “AllocateinLOH”.  Now we have solved the reason behind the High CPU usage in GC because of LOH.

The “allocate_large_object” is not documented by Microsoft as a public API and I don’t know whether the name would be same going forward from .NET framework 4.0.  This holds good until .NET framework 3.5. The idea behind this is just digging in to the framework can give us some information which has saved us valuable time and effort.

About Naveen
Write code.

4 Responses to Identifying High CPU in GC (.NET) because of LOH – using Windbg

  1. Dested says:

    Interesting!

  2. Pingback: Interesting Finds: 2010 02.20 - gOODiDEA.NET

  3. Pingback: Get Managed and Native Call Stacks from Event Tracing for Windows (ETW) « Naveen's Blog

  4. Pingback: Windbg QuickStart guide (Part 2 - hangs) - Riham Selim's Blog - Site Home - MSDN Blogs

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Follow

Get every new post delivered to your Inbox.

%d bloggers like this: