Beware Tracing in ASP.NET can lead to Memory leaks eventually OOM Part1

Today while helping my colleague AnilKP to debug a memory leak issue for w3wp.exe. It was the perfect example to demonstrate scenario where memory leaks were self induced. Here is the complete saga

End customer complained that they had noticed worker process(w3wp.exe) hogs lots of memory. They have notices 1.2 GB process size in the task manager.

Time to look into the w3wp.exe dumps in windbg

Step1)

Look at !address –summary output

-------------------- Usage SUMMARY --------------------------
    TotSize (      KB)   Pct(Tots) Pct(Busy)   Usage
   13c9d000 (  724212) : 15.46%    53.42%    : RegionUsageIsVAD
   5af34000 ( 1490128) : 71.06%    00.00%    : RegionUsageFree
    bffe000 (  196600) : 09.37%    32.39%    : RegionUsageImage

RegionUsageIsVAD indicates Virtual Allocation possibly by .NET

 

Step2)

Let’s check who is making those allocations in RegionUsageIsVad

!Load psscor2

!dumpheap –stat [ Top Memory consumer]

Statistics:
        MT    Count    TotalSize Class Name

…
…
0x0eda1754      1,317     1,067,520 System.Char[]
0x65246e44      1,037     1,074,332 System.Data.RBTree`1+Node[[System.Int32, mscorlib]][]
0x0eda2b54     59,011     1,416,264 System.Collections.ArrayList
0x65242d0c      6,053     1,791,688 System.Data.DataTable
0x0eda2cc0     25,292     2,196,752 System.Int32[]
0x6524508c     43,143     2,761,152 System.Data.DataRow
0x0eda3274     13,099     3,051,624 System.Collections.Hashtable+bucket[]
0x65244ff8     21,658     3,205,384 System.Data.DataColumn
0x0eda3594      1,093     3,767,080 System.Byte[]
0x65245dcc      6,589     6,826,204 System.Data.RBTree`1+Node[[System.Data.DataRow, System.Data]][]
0x0ed742f4     93,592    14,581,740 System.Object[]
0x0eda0b24    489,198    31,431,000 System.String

Time to see if you can spot the difference.

OK, again have a closer look at !dumpheap –stat output. (I’ve bolded the necessary items)

I can tell you from my experience if you see most of Objects of type System.Data.* or Char[] or Object[] or Int32[] / DateTime[] /DataColumn/DataRow. This would indicates probably you have lots of datatables loaded up in the memory. These objects are also internal representation of the datatables.

 

Step3)

Check !dumpdatables

DataTable       Rows    Columns    DataSet     nextRowID ColumnCount
-------------------------------------------------------------------------

 

0x4813980 0x4813c8c 0x4813b3c 0x480bd08            57         2

0x469e050 0x469e35c 0x469e20c 0x46963d8            57         2

0x468e4f8 0x468e804 0x468e6b4 0x4686880            57         2

0x446bf90 0x446c29c 0x446c14c 0x4464318            57         2

0x4452834 0x4452b40 0x44529f0 0x444abbc            57         2

0x4147090 0x414739c 0x414724c 0x413f418            57         2

0x411d27c 0x411d588 0x411d438 0x4115604            57         2

0x3e02094 0x3e023a0 0x3e02250 0x3dfa41c            57         2

0x3dc9f50 0x3dca25c 0x3dca10c 0x3dc22d8            57         2

0x3dacc7c 0x3dacf88 0x3dace38 0x3da5004            57         2

Total 5,158 DataTable objects

Looking for root for couple of Datatables (random datatables)

 

0:000> !gcroot 0x42c3d5c
Scan Thread 28 OSThread f24
Scan Thread 30 OSThread 151c
DOMAIN(14F78880):HANDLE(Pinned):198d11fc:Root:  0b66aac8(System.Object[])->
03931098(System.Web.HttpRuntime)->
03931130(System.Web.Util.Profiler)->
  0395d060(System.Collections.Queue)->
  0395d084(System.Object[])->
  042bc0e4(System.Data.DataSet)->
  042bc150(System.Data.DataTableCollection)->
  042bc174(System.Collections.ArrayList)->
  042c26f0(System.Object[])->
  042c3d5c(System.Data.DataTable)

This indicates Datatables and up till Dataset are all hooked up into System.Web.Util.Profiler objects.

Since System.Web.Util.Profiler is object which corresponds to Tracing in ASP.NET!

0:000> !do 03931130
Name: System.Web.Util.Profiler
Fields:
      MT    Field   Offset                 Type VT     Attr    Value Name
0eda2d70  4003139        8         System.Int32  1 instance      500 _requestsToProfile
0ed99008  400313a        4 ...Collections.Queue  0 instance 0395d060 _requests
0ed745f0  400313b       10       System.Boolean  1 instance        0 _pageOutput
0ed745f0  400313c       11       System.Boolean  1 instance        0 _isEnabled
0ed745f0  400313d       12       System.Boolean  1 instance        1 _oldEnabled
0ed745f0  400313e       13       System.Boolean  1 instance        1 _localOnly
0ed745f0  400313f       14       System.Boolean  1 instance        0 _mostRecent
66116d80  4003140        c         System.Int32  1 instance        0 _outputMode

Since each app domain application would have its own System.Web.Util.Profiler objects. Now point of concern is which application’s web.config has <trace enabled=true ?

0:000> !dumpheap -type System.Web.Util.Profiler -stat
Using our cache to search the heap.
Statistics:
        MT   Count    TotalSize Class Name
0x66149efc        8          224 System.Web.Util.Profiler
Total 8 objects, Total size: 224

We have 8 objects for System.Web.Util.Profiler meaning we have 8 application domain loaded up in the process

It goes inline with the output of !dumpdomain -Stat

0:000> !dumpdomain -stat
    Domain     Num Assemblies     Size Assemblies     Name
7a3d4c80                  0                   0     System Domain
7a3d45d0                 69         133,572,096     Shared Domain
000f1040                 12          60,818,432     DefaultDomain
001137d0                 86         122,207,232     /LM/W3SVC/545012659/ROOT/VMM2012RTMCU1-1-129775789338064151
10b1a200                 30          88,698,368     /LM/W3SVC/545012659/ROOT/RSS-2-129775803359669931
10b4f860                 85         132,836,864     /LM/W3SVC/545012659/Root/ASPJP-3-129775813303229011
14defc38                 52         117,025,792     /LM/W3SVC/545012659/ROOT/ASPEN-4-129775819138585720
14e5ab30                 64         133,910,016     /LM/W3SVC/545012659/ROOT/ASPFR-5-129776695605329661
14ef07f8                 30          87,609,344     /LM/W3SVC/545012659/ROOT/ASPDE-6-129776855254139345
14f78880                 43          93,102,080     /LM/W3SVC/545012659/Root/Accounts-7-129776874660016745

 

Here is the way to figure out our Profilers object belongs to which App Domain

03931098(System.Web.HttpRuntime)->
03931130(System.Web.Util.Profiler)->

 

:000> !do 03931098
Name: System.Web.HttpRuntime

Fields:
      MT    Field   Offset                 Type VT     Attr    Value Name

66149efc  400110b       14 ...Web.Util.Profiler  0 instance 03931130 _profiler
66149f44  400110c       18 ...estTimeoutManager  0 instance 0393114c _timeoutManager
66151b78  400110d       1c ....Web.RequestQueue  0 instance 0395c13c _requestQueue

0eda0b24  4001128       4c        System.String  0 instance 03951420 _codegenDir
0eda0b24  4001129       50        System.String  0 instance 0392cac4 _appDomainAppId
0eda0b24  400112a       54        System.String  0 instance 0392cb48 _appDomainAppPath
6614a32c  400112b       58 ...m.Web.VirtualPath  0 instance 03931478 _appDomainAppVPath
0eda0b24  400112c       5c        System.String  0 instance 0392cc98 _appDomainId
0ed745f0  400112d       80       System.Boolean  1 instance        1 _debuggingEnabled
0eda3594  400112e       60        System.Byte[]  0 instance 00000000 _appOfflineMessage

0:000> !do 0392cb48
Name: System.String
String: C:\Inetpub\wwwroot\Accounts

 

Aha looking into Web.config in C:\Inetpub\wwwroot\Accounts we did found

<trace enabled="true" localOnly="true" pageOutput="true|false" requestLimit="500" />

To sum up you should always make sure Trace and Debug attribute should be false in your production environment to avoid self inducing memory leaks!

At this point developer responsible for this happening is to be given 20 lashes (but only after he or she has fixed this problem). 

If you like my post you can buy me a cup of coffee!