Windbg tips, Dump all Objects with the same type loop with .foreach

Case, there are a lot Memory get used by some objects with the same type.  let’s say the type is String here, how can we dump all those strings.

how to, list all those object ids, and run DumpObject.   .for each

here is a Demo.

static void Main(string[] args)       {           string[] buffer = new string[10];           for (int i = 0; i < 10; i++)           {               //big strings               buffer[i] = new string('-', 20*1024);           }           Console.ReadLine();       }

//List all those string whose size is over 20K

!DumpHeap -type System.String -min 20000 0:004> !DumpHeap -type System.String -min 20000 Address       MT     Size 012d93bc 793308ec    32180     013155e4 793308ec    45832     0133d5a8 793308ec    32180     013597c4 793308ec    40980     013637d8 793308ec    40980     0136d7ec 793308ec    40980     01377800 793308ec    40980     01381814 793308ec    40980     0138b828 793308ec    40980     0139583c 793308ec    40980     0139f850 793308ec    40980     013a9864 793308ec    40980     013b3878 793308ec    40980

the address Column displays the ddress for each string. Let me pick up the red one.

0:004> !do 013b3878
Name: System.String
MethodTable: 793308ec
EEClass: 790ed64c
Size: 40978(0xa012) bytes
(C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
String: --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Fields:
      MT    Field   Offset                 Type VT     Attr    Value Name
79332b38  4000096        4         System.Int32  1 instance    20481 m_arrayLength
79332b38  4000097        8         System.Int32  1 instance    20480 m_stringLength
793315cc  4000098        c          System.Char  1 instance       2d m_firstChar
793308ec  4000099       10        System.String  0   shared   static Empty
    >> Domain:Value  001599c8:012d1198 <<
7933151c  400009a       14        System.Char[]  0   shared   static WhitespaceChars
    >> Domain:Value  001599c8:012d18cc <<

If you want to List all the strings , only display ID. 0:004> !DumpHeap -type System.String -min 20000 -short 012d93bc 013155e4 0133d5a8 013597c4 013637d8 0136d7ec 01377800 01381814 0138b828 0139583c 0139f850 013a9864 013b3878

 

then run loop .foreach. .foreach (address  {!DumpHeap -type System.String -min 20000 -short }) {!do ${address} } //will display all strings

.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.

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

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.

for the big one. !do 022d3250

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.

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

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

open the live stack via windbg.

pick one anyone like 05 ~5s !clrstack

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

 

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.

Identifying High CPU in GC caused By Json.NET Newtonsoft.Json.JsonReader.ParseString windbg

just get a high CPU case, Here is the way I narrow down the issues.

Problems: IIS get high CPU, even only small requests been forwarded to this server.

Answer: something wrong with the json.net, need to update the dll to latest version. http://json.codeplex.com/releases/view/50552

receipt to locate the problem.

Create a Memory Dump using the DebugDiag. http://www.microsoft.com/downloads/en/details.aspx?FamilyID=28bd5941-c458-46f1-b24d-f60151d875a3&displaylang=en

Also copy 3 dlls from production server to debug machine. follow

windbg:PDB symbol for mscorwks.dll not loaded when you debug dump of .net app or silverlight apps and How to configure WinDbg to run other versions of the .NET

to make sure the windbg pick up the right extensions.

What are those CPU threads doing? pick up the smoking gun threads

 

.time 0:055> .time Debug session time: Thu Oct  7 09:23:37.000 2010 (GMT-7) System Uptime: 0 days 7:13:54.707 Process Uptime: 0 days 7:10:08.000   Kernel time: 0 days 23:44:52.000   User time: 0 days 14:44:43.000

How about CPU threads , time spending.

!runaway 0:055> !runaway User Mode Time   Thread       Time   32:930       0 days 1:44:11.109   30:914       0 days 1:25:19.343   34:940       0 days 1:16:02.093   39:9e4       0 days 1:14:45.171   31:938       0 days 1:14:08.984   25:17ec      0 days 1:13:34.687   33:6f4       0 days 1:12:02.671   29:17fc      0 days 1:10:18.765   40:9e8       0 days 1:09:28.203   27:17f4      0 days 1:08:49.453   37:7d0       0 days 1:07:50.390   35:3e8       0 days 1:07:15.718   36:998       0 days 1:07:10.687   38:9d8       0 days 1:07:08.968   28:17f8      0 days 0:59:04.093   26:17f0      0 days 0:58:39.687   65:1f74      0 days 0:14:17.843   44:ce8       0 days 0:12:41.843   52:d2c       0 days 0:12:38.515   53:d30       0 days 0:12:34.359   55:d38       0 days 0:11:53.093   54:d34       0 days 0:11:44.203   45:cec       0 days 0:11:42.875   51:d28       0 days 0:11:36.093   62:1b74      0 days 0:11:20.921   46:cf0       0 days 0:11:13.515

the top 15 threads using a lot CPU cycles. What are they doing Now.

Switch the first thread, #32 ~32s !clrstack 0:032> !clrstack OS Thread Id: 0x930 (32) Unable to walk the managed stack. The current thread is likely not a managed thread. You can run !threads to get a list of managed threads in the process thread 32 is not a managed thread. but that doesn’t exclude our CLR code from the bad lists. then run kb kb 0:032> kb ChildEBP RetAddr  Args to Child              02f3f688 7c827d29 77e61d1e 00000358 00000000 ntdll!KiFastSystemCallRet 02f3f68c 77e61d1e 00000358 00000000 00000000 ntdll!ZwWaitForSingleObject+0xc 02f3f6fc 79e8c5f9 00000358 ffffffff 00000000 kernel32!WaitForSingleObjectEx+0xac 02f3f740 79e8c52f 00000358 ffffffff 00000000 mscorwks!PEImage::LoadImage+0x1af 02f3f790 79e8c54e ffffffff 00000000 00000000 mscorwks!CLREvent::WaitEx+0x117 02f3f7a4 79fd4417 ffffffff 00000000 00000000 mscorwks!CLREvent::Wait+0x17 02f3f7e8 79fcfd70 000f49b8 00000006 00000000 mscorwks!SVR::t_join::join+0xae 02f3f828 79fcf35d 00000002 00000000 000f49b8 mscorwks!SVR::gc_heap::mark_phase+0x176 02f3f854 79fcf77d 00000000 ffffffff 000f49b8 mscorwks!SVR::gc_heap::gc1+0x46 02f3f874 79fcf283 00000000 00000000 000f49b8 mscorwks!SVR::gc_heap::garbage_collect+0x246 02f3f898 79f23b6a 00000000 00000000 00000000 mscorwks!SVR::gc_heap::gc_thread_function+0x6a 02f3ffb8 77e6482f 000f49b8 00000000 00000000 mscorwks!SVR::gc_heap::gc_thread_stub+0x92 02f3ffec 00000000 79f23b1c 000f49b8 00000000 kernel32!BaseThreadStart+0x34

thread 32 is working on GC, which is CPU intensive.
then try other top cpu intensive threads they did the same thingg, Working on GC

0:038> kb ChildEBP RetAddr  Args to Child              030bf088 7c827d29 77e61d1e 00000358 00000000 ntdll!KiFastSystemCallRet 030bf08c 77e61d1e 00000358 00000000 00000000 ntdll!ZwWaitForSingleObject+0xc 030bf0fc 79e8c5f9 00000358 ffffffff 00000000 kernel32!WaitForSingleObjectEx+0xac 030bf140 79e8c52f 00000358 ffffffff 00000000 mscorwks!PEImage::LoadImage+0x1af 030bf190 79e8c54e ffffffff 00000000 00000000 mscorwks!CLREvent::WaitEx+0x117 030bf1a4 79fd4417 ffffffff 00000000 00000000 mscorwks!CLREvent::Wait+0x17 030bf1e8 79fcfd70 000fc048 00000006 00000000 mscorwks!SVR::t_join::join+0xae 030bf228 79fcf35d 00000002 00000000 000fc048 mscorwks!SVR::gc_heap::mark_phase+0x176 030bf254 79fcf77d 00000000 ffffffff 000fc048 mscorwks!SVR::gc_heap::gc1+0x46 030bf274 79fcf283 00000000 00000000 000fc048 mscorwks!SVR::gc_heap::garbage_collect+0x246 030bf298 79f23b6a 00000000 030bf2c0 7c82cce3 mscorwks!SVR::gc_heap::gc_thread_function+0x6a 030bffb8 77e6482f 000fc048 00000000 00000000 mscorwks!SVR::gc_heap::gc_thread_stub+0x92 030bffec 00000000 79f23b1c 000fc048 00000000 kernel32!BaseThreadStart+0x34

search gc context, there is a lot

x mscorwks!SVR::gc_heap::*

So all those busy threads is working on GC, which thread triggered the Demand for GC? that will be the next question.

time to check out those green threads. which consumes rest quota of the CPU

65:1f74      0 days 0:14:17.843   44:ce8       0 days 0:12:41.843   52:d2c       0 days 0:12:38.515   53:d30       0 days 0:12:34.359   55:d38       0 days 0:11:53.093   54:d34       0 days 0:11:44.203   45:cec       0 days 0:11:42.875   51:d28       0 days 0:11:36.093   62:1b74      0 days 0:11:20.921   46:cf0       0 days 0:11:13.515

 

Switch to thread 65 or 44 ~65s !clrstack

the stack means in the shopping cart page, it will use json.net to parse some value. in our case, the values is stord in Cookie.

Is this tread is asking for more memory. It is, Let me show you why?

kb

1, it try to create a big array, then NO space. ask for runtime to issue a gc.

then for us, we get very big value to parse. there are some thing wrong with the cookie system. Update to the new version will get better performance

anyway, for Json Deserialization. first make sure the size is reasonable before you parse it.