Tuesday, October 12, 2010

.NET GC Large Objects, CPU intensive.

you may get the following symbol, “CPU is high , around 40-50% percent, Memory usage is reasonable or very low”

cause? could be the GC problem. which is CPU intensive. ( I have a lot Memory, why bothering a GC? the depends. short story, If you put some big objects or big arrays over 85K, CLR will treat that differently. )

given a basic application.

int less85k = 8 * 1024;
int more85k = 86 * 1024;

string lessstring = new string('l', less85k);
string moresring = new string('m', more85k);

two string will go to different GC zone. one is regular gc, another one is Large object gc.

you can tell from windbg, or sos extension.

image

when I run !DumpHeap –type System.String –min 10000

image

Obje A is in the generation 2 regular GC ( you can tell from obj address, 012d is betwen 12d000 and 012e0030)

when you run !do 012d9bd4  to dump the object, you can tell it’s the smaller string.

image

for the big one. !do 022d3250

image

Now they are in different GC zone. If there are a lot string operations. let’s we keep create the big strings.

for (int i = 0; i < 10; i++)
        {
            ThreadPool.QueueUserWorkItem(
                sender =>
                {
                    while (true)
                    {
                        string moresring = new string('m', more85k);
                    }
                }
                );
        }

 

CPU is high, Memory usage is low.

image

a lot CPU kernel time.  Big object GC caused more context switching for CPU.

image

TURN on the performance counter, chose the clr memory. there are center amount of GC time.

image

open the live stack via windbg.

image

pick one anyone like 05 ~5s !clrstack

image

kb for unmanged stack (allocate large objects and adjust the limit clr)

0:005> kb
ChildEBP RetAddr  Args to Child             
010af7f4 79f926b3 0237f2c0 0002b028 010af8c0 mscorwks!WKS::gc_heap::adjust_limit_clr+0xd6
010af88c 79f926ce 010af8c0 0002b018 00000003 mscorwks!WKS::gc_heap::try_allocate_more_space+0x5bb
010af8a0 79f9a2dc 010af8c0 0002b018 00000003 mscorwks!WKS::gc_heap::allocate_more_space+0x11
010af8e0 79eee84a 0002b012 00000000 0015ef30 mscorwks!WKS::gc_heap::allocate_large_object+0x54
010af8f8 79e73291 001804c8 0002b012 00000000 mscorwks!WKS::GCHeap::Alloc+0x66
010af914 79e7d8d4 0002b012 00000000 00000000 mscorwks!Alloc+0x60
010af950 79e99056 00015801 fe2369b0 00000000 mscorwks!SlowAllocateString+0x29
010af9f4 792e1040 00000000 012de030 012ddc74 mscorwks!FramedAllocateString+0xa1
010afa2c 792c9dff 012ddc8c 792e019f 00982010 mscorlib_ni+0x221040
010afa34 792e019f 00982010 012ddc74 012ddc8c mscorlib_ni+0x209dff
010afa48 792ca363 012ddc74 00000000 012ddc74 mscorlib_ni+0x22019f
010afa60 792ca1f9 25f33da1 010afaa4 00180488 mscorlib_ni+0x20a363
010afa78 79e71b4c 77e69433 77e6945f 010afb08 mscorlib_ni+0x20a1f9
010afa88 79e821b1 00000000 00000000 010afc10 mscorwks!CallDescrWorker+0x33
010afb08 79e82cfa 00000000 00000000 010afc10 mscorwks!CallDescrWorkerWithHandler+0xa3
010afb28 79e82d3b 00000000 00000000 010afc10 mscorwks!DispatchCallBody+0x1e
010afb8c 79e82da9 00000000 00000000 010afc10 mscorwks!DispatchCallDebuggerWrapper+0x3d
010afbc0 79f2fd65 00000000 00000000 010afc10 mscorwks!DispatchCallNoEH+0x51
010afc1c 79e9845f 00000000 00000001 00000000 mscorwks!QueueUserWorkItemManagedCallback+0x59
010afc30 79e983fb 010afd0c 010afcb8 79f7759b mscorwks!Thread::DoADCallBack+0x32a

 

if we try the same code for small objects.

for (int i = 0; i < 10; i++)
        {
            ThreadPool.QueueUserWorkItem(
                sender =>
                {
                    while (true)
                    {
                        string lessstring = new string('l', less85k);
                    }
                }
                );
        }

CPU is also High, but more on usertime

image

 

0:014> !clrstack
OS Thread Id: 0x1fac (14)
ESP       EIP    
03a1f5a4 79f9255a [HelperMethodFrame: 03a1f5a4]
03a1f5fc 792e1040 System.String.CtorCharCount(Char, Int32)
03a1f618 00ea01bd ConsoleApplication10.Program+<>c__DisplayClass2.<Main>b__0(System.Object)
03a1f634 792c9dff System.Threading._ThreadPoolWaitCallback.WaitCallback_Context(System.Object)
03a1f63c 792e019f System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
03a1f654 792ca363 System.Threading._ThreadPoolWaitCallback.PerformWaitCallbackInternal(System.Threading._ThreadPoolWaitCallback)
03a1f668 792ca1f9 System.Threading._ThreadPoolWaitCallback.PerformWaitCallback(System.Object)
03a1f7f8 79e71b4c [GCFrame: 03a1f7f8]
0:014> kb
ChildEBP RetAddr  Args to Child             
03a1f42c 79f926b3 015b8cc0 00004020 00187fd0 mscorwks!WKS::gc_heap::adjust_limit_clr+0xd6
03a1f4c4 79f926ce 00187fd0 00004014 00000000 mscorwks!WKS::gc_heap::try_allocate_more_space+0x5bb
03a1f4d8 79f92769 00187fd0 00004014 00000000 mscorwks!WKS::gc_heap::allocate_more_space+0x11
03a1f4f8 79e73291 00187fd0 00004012 00000000 mscorwks!WKS::GCHeap::Alloc+0x3b
03a1f514 79e7d8d4 00004012 00000000 00000000 mscorwks!Alloc+0x60
03a1f550 79e99056 00002001 47a58a5d 00000000 mscorwks!SlowAllocateString+0x29
*** WARNING: Unable to verify checksum for C:\WINDOWS\assembly\NativeImages_v2.0.50727_32\mscorlib\9adb89fa22fd5b4ce433b5aca7fb1b07\mscorlib.ni.dll
03a1f5f4 792e1040 00000000 012d7468 012d72d0 mscorwks!FramedAllocateString+0xa1
03a1f62c 792c9dff 012d72e8 792e019f 00982010 mscorlib_ni+0x221040
03a1f634 792e019f 00982010 012d72d0 012d72e8 mscorlib_ni+0x209dff
03a1f648 792ca363 012d72bc 00000000 012d72d0 mscorlib_ni+0x22019f
03a1f660 792ca1f9 25f82416 03a1f6a4 00187f90 mscorlib_ni+0x20a363
03a1f678 79e71b4c 77e69433 00150178 03a1f708 mscorlib_ni+0x20a1f9
03a1f688 79e821b1 00000000 00000000 03a1f810 mscorwks!CallDescrWorker+0x33
03a1f708 79e82cfa 00000000 00000000 03a1f810 mscorwks!CallDescrWorkerWithHandler+0xa3
03a1f728 79e82d3b 00000000 00000000 03a1f810 mscorwks!DispatchCallBody+0x1e
03a1f78c 79e82da9 00000000 00000000 03a1f810 mscorwks!DispatchCallDebuggerWrapper+0x3d
03a1f7c0 79f2fd65 00000000 00000000 03a1f810 mscorwks!DispatchCallNoEH+0x51
03a1f81c 79e9845f 00000000 00000001 00000000 mscorwks!QueueUserWorkItemManagedCallback+0x59
03a1f830 79e983fb 03a1f90c 03a1f8b8 79f7759b mscorwks!Thread::DoADCallBack+0x32a
03a1f8c4 79e98321 03a1f90c 47a586a9 00000001 mscorwks!Thread::ShouldChangeAbortToUnload+0xe3

just regular space allocation.

No comments:

 
Locations of visitors to this page