Monday, November 12, 2012

.NET crash dump debugging

Yet again I was debugging an application using WinDbg recently. Here is a list of more commands, that I found useful. First, when I load WinDbg under Windows 7 i first run:
*SRV*DownstreamStore*http://msdl.microsoft.com/download/symbols*
.sympath srv*
.reload
.loadby sos mscorwks
Then I install in some folder useful extension. Those extensions are useful, especially for GC Collection debugging, and searching for deadlocks. A brief description of commands. And I run:
.load C:\worek\sosex\sosex
With an extension installed I can check for deadlocks
!locks                     -- original WinDbg command
!dlk                       -- really nice extension
After checking for deadlocks I look at a memory. I am interested in how much memory is used. Unknown memory is a virtual memory.
!address -summary
......
--- Usage Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal
Free                    713      7fb`d81ce000 (   7.984 Tb)           99.80%
<unknown>        2328        3`fb052000 (  15.922 Gb)  95.78%    0.19%
Heap                    188        0`18782000 ( 391.508 Mb)   2.30%    0.00%
Image                  3046        0`11147000 ( 273.277 Mb)   1.61%    0.00%
Stack                   303        0`03280000 (  50.500 Mb)   0.30%    0.00%
Other                    19        0`001bc000 (   1.734 Mb)   0.01%    0.00%
TEB                     101        0`000ca000 ( 808.000 kb)   0.00%    0.00%
PEB                       1        0`00001000 (   4.000 kb)   0.00%    0.00%
.....
To see what is inside virtual memory one can run:
!address -f:VAR
Then I look at types in memory. I am looking at a number of objects allocated per type, and amount of memory used. String is primitive type that eats huge amount of memory.
!dumpheap -stat
.........
000007fef8eeeb88   109006      4360240 System.Collections.ArrayList
000007fef8ee7590   190421      4570104 System.Object
000007ff009bfa08    24963      4792896 Sitecore.Data.Items.Item
000007ff00a76300   102363      9826848 Sitecore.Caching.Cache+CacheEntry
000007fef8eef5f8   156519     13773672 System.Collections.Hashtable
000007fef8ed5a90   181410     17197296 System.Object[]
000007ff009bc690   573156     27511488 Sitecore.Data.ID
000007fef8eefce0     6083     43988712 System.Byte[]
000007fef8eef7c0   156694     63591264 System.Collections.Hashtable+bucket[]
000007fef8ee7ca0   903961    149734600 System.String
00000000011b5cc0     8161   1172482272      Free
Total 3615363 objects
Fragmented blocks larger than 0.5 MB:
            Addr     Size      Followed by
0000000143871e38    0.7MB 000000014392e858 System.String
0000000143b48248    0.6MB 0000000143bdb670 System.String
000000023f531080    9.1MB 000000023fe4f130 System.Threading.Overlapped
To identify who is holding a type:
!dumpheap -type TTC.TT.Nelson.Services.Data.DepartureData
...
Heap 0
         Address               MT     Size
00000000ff453010 000007ff01591f00       88     
0000000100115190 000007ff015925a8       64     
0000000100116a38 000007ff015925a8       64     
0000000100658c70 000007ff015925a8       64     
0000000100658cb0 000007ff015c6b10       64     
0000000100658d18 000007ff015925a8       64     
0000000100800e88 000007ff01591f00       88     
0000000100800fb0 000007ff01591f00       88     
00000001008010d8 000007ff01591f00       88     
0000000100801200 000007ff01591f00       88     
0000000100801328 000007ff01591f00       88     
....
I go to a specific address and try to see a trace:
!gcroot 00000000ff453010
...
Scan Thread 99 OSTHread 1384
DOMAIN(000000000263FAA0):HANDLE(Pinned):16415c0:Root:00000001ff419258(System.Object[])->
0000000140791438(System.Func`2[[TTC.TT.Nelson.Services.Data.DepartureData, TTC.TT.Nelson],[TTC.TT.Entities.TropicsAvailabilityStatus, TTC.TT.Entities]])
...
To see just managed threads:
!threads
...
                                              PreEmptive                                                Lock
       ID OSID        ThreadOBJ     State   GC     GC Alloc Context                  Domain           Count APT Exception
  10    1  e90 00000000025ec820      8220 Enabled  0000000000000000:0000000000000000 00000000025e7950     0 Ukn
  20    2  560 00000000026003f0      b220 Enabled  0000000000000000:0000000000000000 00000000025e7950     0 MTA (Finalizer)
  21    3  41c 000000000263e700    80a220 Enabled  0000000000000000:0000000000000000 00000000025e7950     0 MTA (Threadpool Completion Port)
  22    4 1270 000000000263f4d0      1220 Enabled  0000000000000000:0000000000000000 00000000025e7950     0 Ukn
  25    8 14a0 0000000004a701f0   200b020 Enabled  0000000000000000:0000000000000000 000000000263faa0     0 MTA
...
To see threads with a stack assigned to a thread:
~*e !CLRStack
...
OS Thread Id: 0x14a0 (25)
Child-SP         RetAddr          Call Site
0000000008fdede0 000007fef8da2bbb Sitecore.IO.FileWatcher.Worker()
0000000008fdee30 000007fef8e3aa7d System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
0000000008fdee80 000007fef9cc0282 System.Threading.ThreadHelper.ThreadStart()
OS Thread Id: 0x3d8 (26)
Child-SP         RetAddr          Call Site
000000000918e950 000007fef8da2bbb Sitecore.IO.FileWatcher.Worker()
000000000918e9a0 000007fef8e3aa7d System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
000000000918e9f0 000007fef9cc0282 System.Threading.ThreadHelper.ThreadStart()
...
To see what objects are waiting to be finalized:
!finalizequeue
...
000007fef8ee88c0       76         3648 System.Globalization.AgileSafeNativeMemoryHandle
000007fef8ed5270       35         4200 System.IO.FileStream
000007fef8ee8740       57         5928 System.Threading.Thread
000007fef5380810      239        13384 System.Web.DirMonCompletion
000007fef8edf1b8      444        14208 System.WeakReference
000007fef52fc188      319        25520 System.Web.UI.WebControls.Style
000007fef8f10548      956        68832 System.Reflection.Emit.DynamicResolver
000007fef5391310    18366       734640 System.Web.HttpResponseUnmanagedBufferElement
To see CPU utilization with info about how many threads/timers are in use:
!threadpool
...
CPU utilization 61%
Worker Thread: Total: 10 Running: 0 Idle: 10 MaxLimit: 400 MinLimit: 4
...
To profile a cache
!dumpheap -type System.Web.Caching.Cache -stat
Heap 3
total 5288 objects
------------------------------
total 22083 objects
Statistics:
              MT    Count    TotalSize Class Name
000007fef53815a0        1           24 System.Web.Caching.CacheKeyComparer
000007fef5381090        1           24 System.Web.Caching.Cache
000007fef5381848        1           32 System.Web.Caching.CacheKey
000007fef53813e0        1           40 System.Web.Caching.CacheMultiple
...
Then I follow the System.Web.Caching.Cache object:
!dumpheap -mt 000007fef5381090
...
Heap 1
         Address               MT     Size
000000013f41d210 000007fef5381090       24 
...
Heap 3
         Address               MT     Size
total 0 objects
------------------------------
total 1 objects
Statistics:
              MT    Count    TotalSize Class Name
000007fef5381090        1           24 System.Web.Caching.Cache
And I dump the object to see the stack:
!do 000000013f41d210
              MT    Field   Offset                 Type VT     Attr            Value Name
000007fef5380ed0  40013aa        8 ...ing.CacheInternal  0 instance 000000013f41d358 _cacheInternal
000007fef8f281e0  40013a8      370      System.DateTime  1   shared           static NoAbsoluteExpiration
                                 >> Domain:Value  00000000025e7950:NotInit  000000000263faa0:000000013f423990 0000000004d49820:NotInit  <<
000007fef8f280e0  40013a9      378      System.TimeSpan  1   shared           static NoSlidingExpiration
                                 >> Domain:Value  00000000025e7950:NotInit  000000000263faa0:000000013f4239a8 0000000004d49820:NotInit  <<
000007fef5380dd8  40013ab      380 ...emRemovedCallback  0   shared           static s_sentinelRemovedCallback
                                 >> Domain:Value  00000000025e7950:NotInit  000000000263faa0:000000013f423a08 0000000004d49820:NotInit  <<
To dump LHO heap I use
!dumpheap -min 85000
...
00000002353fa698 00000000011b5cc0 19578352 Free
00000002366a6488 000007fef8ee7ca0   114496     
00000002366c23c8 00000000011b5cc0 134666512 Free
000000023e72fcd8 000007fef8eefce0   524312     
000000023e7afcf0 00000000011b5cc0  2618528 Free
000000023ea2f190 000007fef8eef7c0   242496     
total 118 objects
------------------------------
total 450 objects
Statistics:
              MT    Count    TotalSize Class Name
000007ff01101028        1        98304 System.Data.Linq.IdentityManager+StandardIdentityManager+IdentityCache`2+Slot[[TTC.TT.Nelson.DataAccess.ZPermanentRedirect, TTC.TT.Nelson],[System.Int32, mscorlib]][]
000007fef8ee9598        1       131096 System.Char[]
000007fef8ed5a90        2       262208 System.Object[]
000007ff01ea0858        1       524280 System.Data.Linq.IdentityManager+StandardIdentityManager+IdentityCache`2+Slot[[TTC.IV.Nelson.DataAccess.ZSitecoreUrl, TTC.IV.Nelson],[System.Guid, mscorlib]][]
000007ff010d6450        1       524280 System.Data.Linq.IdentityManager+StandardIdentityManager+IdentityCache`2+Slot[[TTC.TT.Nelson.DataAccess.ZSitecoreUrl, TTC.TT.Nelson],[System.Guid, mscorlib]][]
000007fef8eef7c0       15      6673440 System.Collections.Hashtable+bucket[]
000007fef8eefce0       22     40672944 System.Byte[]
000007fef8ee7ca0      277     48983200 System.String
00000000011b5cc0      130   1151450896      Free
...
To see what's inside GC collection 2, just be careful it may crash your WinDbg session.
!dumpgen 2

No comments: