If broken it is, fix it you should

Following my post about how to troubleshoot a low CPU performance issue with VSTS Test, I will now do the same for lab 4 where we have high CPU in GC.

The scenario is pretty similar in that we have a page (http://localhost/BuggyBits/AllProducts.aspx) that seems to be taking a lot of time to execute.  We also see that the w3wp.exe process sits at very high CPU ~100% during the time this page executes.

Using Windbg in the lab, we saw that the issue here was that we were concatenating a very large string in a loop.  This was generating a lot of full collections since we were constantly exhausting the large object heap, causing us to spend a lot of time in the GC.  Check out the review for Lab 4 for more details on the issue.

What are we going to accomplish here?

These are the steps I will go through to narrow down the issue to the string concatenation:

1. Set up a load test for AllProducts.aspx and configure the counter set to include .net and process counters for w3wp.exe

2. Run a sampling performance session to discover that we are spending most of our time in the GC.  Here I will also set up a symbol server to be able to see profiling for some native (non .net) methods.

3. Look at the threashold violations and some interesting .net counters for the load test

4. Run an instrumentation performance session to see in which .net methods we are spending most of our time.

Since I went through how to set up a test project, web test, load test and a performance session in the previous post I will only brush on it here to save some electrons…

Setting up and configuring a load test for AllProducts.aspx

1. Create a new web test with a request to http://localhost/buggybits/allproducts.aspx

2. Create a new load test using the allproducts web test, set it to run for 2 minutes leaving all the rest as defaults.

3. Add w3wp.exe as an instance for .NET CLR Memory counters and Process counters

a. Under Counter Sets, expand the .Net Application counter set. 

b. Right-click on Counter Categories and choose Add Counters. 

c. For the .NET CLR Memory performance category, choose all counters, and w3wp.exe as the instance.

d. Remove _Global from the instance list for .NET CLR Memory by expanding the .NET CLR Memory node in the treeview and removing it under Counter Instances.

Do the same thing for the process counter under Controller.

4. Add the .NET Application counters to the test

a. Under Run Settings, right-click on Counter Set Mappings and choose Manage Counter Sets

b. Click Add Computer, type in localhost and check the checkbox for .NET Application

Running a sampling performance session

1. On the AllProducts.loadtest, click on the Create Performance Session for this Test button to start the performance wizard.

2. Choose Sampling as the profiling method since this is a high CPU situation and click through the rest of the wizard.

3. In the Performance Explorer, start the test by clicking on the Launch with Profiling button.

When the test has finished running, you should see a Performance Report Summary.  Note that this might take a while to produce since the w3wp.exe process will be running at around 100% long after the load test is finished.

The Performance report summary will show that most of the CPU cycles are spent in [mscorwks.dll].  This is because we haven’t yet set up symbols so that the performance report can report the actual methods that are running.

4. Close the report and set up symbols to get some good data.

a. Under tools/options, expand the debugging node and select symbols.

b. Click on the new folder button and type in symsrv*symsrv.dll*c:\webcache*http://msdl.microsoft.com/download/symbols for the path.  This will cause Visual Studio to go out to Microsofts public symbol server to look up symbol files (pdb files).  The path between the ** tells it where to cache local copies of the symbols so it doesn’t have to go out on the internet everytime.

c. Open the report again.  This time you should see messages like

Symbol Engine: Loading symbols for module 'C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\Temporary ASP.NET Files\buggybits\b27906cc\f5f91899\App_Web_b9uwda_7.dll'

in the output window… and the performance report summary should now look something like

Note: It might take a really long time to produce this the first time since it has to download the symbols

From the Performance Report Summary we produced we can see that most of our time is spent in GC related functions.  With this we can make some assumptions but since the GC runs on dedicated threads in the server version of the GC we can’t really see what caused us to GC so much.

Looking at threshold violations and performance counters

If we bring up the load test results for this session, we will find that it has a large number of threshold violation

A threshold violation means that during the test, a treshold rule for a performance counter has been violated.  You can set up rules on your own for counters, saying that for example it should generate a warning when CPU usage goes over 70% or when Available MB is below 100 MB or similar.  

A few of the performance counters have default rules, and if we click on the link to bring up our threshold violations we see that we frequently violate the threshold of 25% set up for the .NET CLR Memory/% Time in GC.

This confirms the suspicions from our sampling session about high CPU in GC being our issue. So now we need to look at what is causing this high CPU in GC.

As mentioned earlier, high CPU in GC usually means that we are doing a lot of full collections (Gen 2) compared to Gen 1 and Gen 0 collections.  Again, look at the lab 4 walkthrough for more details on this…

To see the the values and trend for .NET CLR Memory\% Time in GC,  # Gen 0 Collections, # Gen 1 Collections and # Gen 2 Collections you can bring up the graphs in the LoadTest results and right-click and choose Show Counters on Graph on these counters under Computers/MachineName/.NET CLR Memory.  They will show on the Key Indicators graph.

Here we can see that the number of Gen 0, Gen 1, and Gen 2 collections are very similar, i.e. there is almost a 1:1:1 ratio between them.  Normally, and preferably, we should see a lot of Gen 0 for each Gen 1, and a lot of Gen 1 for each Gen 2.  This 1:1:1 ratio means that pretty much every collection that we make is a full one (Gen 2), since full collections are very expensive comparatively there is no wonder we are spending a lot of our time in the GC.  The average % Time in GC is 81.5% which is extremely high… in a healthy application we should spend somewhere around 5-30% in GC.

Note:  The counter lines are broken in some places, this is because we were running at a 100% CPU so we didn’t get a chance to read the counters…

Again as I mentioned before, the reason for this type of ratio 1:1:1 is usually that we are overloading the large object heap, and when an LOH segment is exhausted we perform a full collection…  so the next question is what is causing this…

In order to figure this out I will run an instrumentation performance session since that will tell us where we are stuck waiting for the GC most of the time…

Running an instrumentation performance session

To run an instrumentation performance session for this test we can simply reuse the same performance session and change the method from sampling to instrumentation in the Performance Explorer

and then rerun the performance session…

Instrumentation means that we add tags in the methods so that we record the times when we enter and leave a method, and thus we can see how long time we are spending in them.

Once the performance session is done, we get the Performance Report Summary (note that again this will not appear until the CPU time starts going down in the process)

The top two methods where we spend most of our time (inclusive, i.e. including the methods it calls) is AllProducts.Page_Load() and System.String.Concat().

Drilling into the Page_Load method (by double clicking it once here and double clicking it again in the functions pane) we get the following:

So here we can see that most of the time spent in the Page_Load method, is actually spent inside the System.String.Concat method.  Extrapolating from the results before we can say that most of the time when we are waiting for a GC, this is triggered by an allocation made in String.Concat, comming from the Page_Load method.

We can double click on the Page_Load method here to get to the code

And here we can see the cause of our issue, i.e. that we are concatentating very large strings (assuming that the dataset is pretty big, which it is in this case), in a loop.

Final thoughts

I know that you need some previous knowledge about how the GC works, what the common causes are for high CPU in GC etc. to jump to some of the conclusions that I jumped to… but still, even without this knowledge, with this method you can drill down to the exact cause of the issue. i.e. the string concatenation…

Hopefully, with these tips you will be able to catch some of your performance issues in the test phase before they get into your production environment:)

Laters,

Tess

I’ve been wanting to dig into the Test features in Visual Studio Team System for a while to “debug” issues during the test phase.  In my previous post I linked to a Swedish screen cast by Mikael Deurell, but for those of you who don’t know Swedish I thought I’d walk through troubleshooting a couple of my labs using the Visual Studio Team System Profiler and Load Tests. 

Problem description

The issue we will troubleshoot comes from lab 1 in my BuggyBits lab set, and the scenario here is that we see that the execution times for the page FeaturedProducts.aspx keep increasing, and under load the page even times out.

Those of you who have walked through the labs will of course know what the underlying issue and resolution is, so please act surprised when you get to the end:)

So what we want to accomplish here is

1. Set up a load test against http://localhost/buggybits/featuredproducts.aspx

2. Profile the application to figure out where we are spending all our time

Note: The steps shown here for profiling should work equally well for profiling any type of application, including winforms applications.

Creating and configuring the test projects

1. Open the BuggyBits website (In visual studio)

2. Add a new Test project called BuggyBits Test

3. Remove the files AuthoringTests.txt, ManualTest1.mht and UnitTest1.cs since we wont be using them

4. Add a new Web Test called Featured.webtest

This will start a recording session for your web test opening up a new browser.  If you get a message “Currently browser extensions are disabled in Internet Explorer” you can press Alt when the Internet Explorer comes up to get the menus and choose view/Exploerer bar/Web Test Recorder 9.0 from the menu to start recording.

Record the test by browsing to http://localhost/BuggyBits/FeaturedProducts.aspx and select stop recording when the page comes back. This will add a request to http://localhost/buggybits/FeaturedProducts.aspx to the web test.  Now, if you wanted to record more requests in the same session you could just continue browsing before you click stop.

5. Add a new Load Test to stress the http://localhost/BuggyBits/FeaturedProducts.aspx page

This will bring up the New Load Test Wizard, you can just skip through til you get to the Test Mix dialog where you add the Featured.webtest test and then skip through again until you reach the Run Settings where you can set the Run duration to 2 or 5 minutes instead of the normal 10 minutes.

Rename the test from LoadTest1.loadtest to FeatureLoad.loadtest when you’re done

Note: There are many things you can do in here including setting up counter sets etc. for your load test, but I will be skipping these for now since we are just going to use the load test to create load for our profiling session.

Running the load test

The load test is now ready to run and you can run it using the run button to see how it fares.

This will bring up a number of graphs showing you the basic counters.  As mentioned before you could also add other counters that you are interested in and set triggers on them but for the purposes of this exercise we will just take a brief look at the standard counter set and move on to the performance session.

The most interesting graphs for this issue are the Page Response Time which shows the Avg. Page Time, i.e. how long each page of the test took to execute, and we can see it increasing throughout the load test which is consistent with the problem description.

In the System under Test graph I am plotting % Processor Time on the machine, and as you can see we are dealing with a low cpu performance issue which means that we are spending most of our time waiting.

Adding a performance session

With the FeatureLoad.loadtest window open, click on the “Create a performance session for this test” button. 

This will add a performance session to the load test.  A performance session allows you to get information about which methods took a long time to execute, which methods allocated the most memory etc. etc. 

When you add a performance session to a test, what you are really doing is creating a performance session, and when you start that performance session the first thing it will do (after attaching to the process (and instrumenting the bits if choosen)) is to start your test. That way you don’t have to both start a perf session and a test, but it would be the same as creating a separate performance session, starting this and then starting your load test.

The performance wizard that comes up has 4 steps

Step 1 – Information – Click next

Step 2 – Specify profiling method,  short and sweet, for high CPU sampling is usually better, for low CPU instrumentation is usually better, since ours is a low cpu we will choose instrumentation  and click next

Step 3 – Specify the application to be profiled – This should be pre populated for us with the http://localhost/BuggyBits application so we can click next

Step 4 – Confirm and finish

Running the performance session

If you open up the Performance Explorer window you should now see a Performance session called FeatureLoad containing your load test and with the profiling method set to Instrumentation

Start the session by clicking the “Launch with Profiler” button

In the output window you should see messages like

You can switch over to the Test Results window to see the test results and if you double click on the FeaturedLoad test in the test results window this will bring up the graphs you saw when running the load test before.

Once the load test is finished, stop your performance session by pressing the stop button in Performance Explorer

Analyzing the results

Now we have collected all the data and we are ready to dig into what caused the performance issue…

In the performance explorer, a new vsp file containing the performance report should now be available in the Reports folder of the FeaturedLoad performance session.

It will automatically start with the Summary view which shows the following for a 2 minute run

By far, the method we have spent the most time in here is the System.Threading.Monitor.Enter method (which basically means that we have been stuck in a lock), and as you can see we have spent 94.56% of our time here.

If we double-click on this it brings us to the functions view, and if we double-click it again we get to the Caller/Callee view which shows us who calls this method.  

In this case we can see that the only method in this test that calls Monitor.Enter is DataLayer.GetFeaturedProducts, so this is where we are stuck in the lock…  If we would have had multiple callers here, we would have been interested in the one/s with most Elapsed Inclusive Time

We can double-click on the GetFeaturedProducts method here to see information about it’s callees, and we can see that Elapsed exclusive time for GetFeaturedProducts is almost 0% so we spend most of our time in the methods we call.  And the time we spend in the callees is topped by the Monitor.Enter method of course where we spend 94,56% of the time, followed by Thread.Sleep where we spend 5,31% of our time…

So now we have a very good idea of where we spend our time, i.e. to resolve the issue we need to be looking at why we are stuck in a lock in this method.

Double-clicking on the GetFeaturedProducts method under Current Function takes us to the actual code

And from here it is a pretty easy task to see what we need to optimize (i.e. the Sleep that is supposed to represent a long database call).   Note that if it would have in fact been a long database query, we would have very likely seen a System.Data.SqlClient.SqlCommand.ExecuteReader or similar as the 2nd topmost method in the callees list for GetFeaturedProducts.

I hope this has given you a brief insight into troubleshooting these kind of issues if you discover them in the test phase, and I will probably follow up with some similar posts for high CPU issues and memory issues as well…

Until then,

Tess

I know that perhaps not that many of you know Swedish, but for those of you who do, you might want to check out Michael Deurell’s nice screen casts about how to use visual studio test system to troubleshoot the issues in the buggybits labs along with some windbg fun…  His screen casts are called “Fräschast i Bandhagen”, just love that name (unfortunately doesn’t translate that well to English:))

http://blogs.msdn.com/deurell/archive/2008/09/30/debugga-i-produktion-eller-testa-bort-i-utveckligsfas.aspx

Laters,

Tess

John Robbins beat me to the punch and wrote an excellent post about using .cmdtree in windbg to ease some .net debugging pain in windbg.

The windbg .cmdtree command allows you to create a popup window in windbg with commands that execute when you click on the respective link...  so you no longer have to remember all the sos commands to get around in your managed dump.

Read his post here and with the command tree text file he provides you will be up and running in no time...  You can also add the command .cmdtree c:\util\sos-cmdtree.txt once you have this set up, to your commands file to get it loaded automatically when you open dumps....   And of course, you can easily customize your commandtree so that you can execute any commands you like.

Really sweet,

Tess

Here are of some of the reader emails I got this week and my answers to them...

• How do I troubleshoot this memory leak
• Debugging techniques for capturing stacks of OOMS
• Do you have a list of Debugging 101 links?
• Debugging managed code in IE
• Getting to dependency properties with sos

Note: some of the emails have been edited to fit better in a Q/A format, hopefully I haven't missed any important bits...

Q: How do I troubleshoot this memory leak

I started observing a slow leak in task manager of about 100 MB / 30 mins, in a web application consisting of WCF services.

In perfmon Gen 0, 1, and 2 collections steadily grew, and Gen 2 size kept growing but Gen 0 and Gen 1 just bounced around staying around the same level.  Private bytes and virtual bytes for the process didn't change much so this didn't allow me to go much further with the steps shown in the lab examples.

The threads (~* kb) were sitting in a state which you mentioned in one of your articles could be ignored, and !dumpheap -stat didn't show one object in particular taking up all the room.

Can you recommend a direction?

Supporting data:

My answer: 

You will always see Gen 1 size and Gen 0 size stay pretty flat since there are limit to how big these can grow to be.  In fact the Gen 0 size is not really the size of Gen 0, rather it is the budget for Gen 0.  These counters are updated at the end of each garbage collection, and at that point Gen 0 will always contain 0 bytes, so the size wouldn't make much sense...

Since Gen 2 is continuously growing, the interesting question here would be, is it growing at approximately the same rate as the process? If so, you have a managed memory issue. You can also check out .net clr memory\#Bytes in all heaps

The dump you have taken is only at around 300 MB (1266a000 ( 301480) : 14.38% : MEM_COMMIT) which makes it a bit hard to say anything about memory usage since dlls and core parts of the framework will take up a large part of that. What I would recommend that you do is to take multiple memory dumps, preferably 2-3 taken about 100 MB apart, and then compare the size of the dumps or MEM_COMMIT, the GC heap sizes with !eeheap -gc to see if they grow at the same rate, and then finally, if they do, then compare the !dumpheap -stat output to see what objects increase the most.

Just judging by your !dumpheap -stat output you seem to have mostly datasets so it might be worthwhile checking the sizes with !objsize on dataset items and !gcroot them to see why they are sticking around. Having said that though, the dump is pretty small so the amount of dataset related items isn’t by any means alarming. Hopefully looking at the sizes etc. of the datasets you can see if they seem to be an issue, comparing it to what you think the application should use.

Q: Debugging techniques for capturing stacks of OOMS

I'd like know what software or technique you use (http://blogs.msdn.com/tess/archive/2008/09/02/outofmemoryexceptions-while-remoting-very-large-datasets.aspx) to capture full stack trace of execution?

Can this technique or software be used for ASP.NET?

My answer:

There are multiple ways to capture the stack trace of an OOM.  The technique I used in this case was to attach to the process with windbg (from the debugging tools for windows) and set a breakpoint on mscorwks!ThrowOutOfMemory

bp mscorwks!ThrowOutOfMemory

This is of course only feasible if you can break into the process, which you usually can't do on a live asp.net application.  In an ASP.NET application you could set up an adplus config file with this breakpoint, and have it take a dump when it encountered the breakpoint...

Creating dumps with Windbg and writing ADPlus Config files

or you can set up GCFailFastOnOOM per http://support.microsoft.com/kb/820745

This article on how to troubleshoot OOMs in ASP.NET with DebugDiag and Perfmon is also very useful in this scenario.

Q: Do you have a list of Debugging 101 links?

I have been reading your blogs and using your Lab Demos. So far they have been great but I was wondering if you had any recommendations about learning the debugging tool a little better. There are points where I get really confused and lost but I will admit that is because I don’t know or understand a command or two (or three) in the debugger. I kind of jumped into this in the middle so I would like to get “back to the basics” and try and understand the debugger a little better before I start debugging.

Any simple Debugging 101 links you could recommend would be greatly appreciated. In the mean time, looking forward to your posts!

My answer:

For debugging basics... have a look at the following posts

Back to Basics - How do I get the memory dumps in the first place? And what is SOS.dll?
Learning .NET debugging
.NET Hang Debugging Walkthrough
ASP.NET Memory Investigation
A big list of debugging resources

and of course the labs mentioned in the email

.NET Debugging Demos - Information and setup instructions

Q: Fragmentation of the LOH

I have been trying to reduce the memory foot print of my application recently and I found something interesting. My application takes advantage of the new Script Combining features in .NET 3.5 SP1 to reduce the number of HTTP requests as well as improve client load time.

After reviewing some memory dumps I am starting to see many large strings stored on the LOH. Many of these strings contain the output of the combined scripts. All of the combined scripts are embedded resources within the System.Web.Extensions.dll as well as our own embedded resources within our custom control library.

Will this cause heavy framentation within the LOH? Are you aware of anything I can do to help this?

Supporting data:

My answer:

I haven't worked a whole lot with this, so I don't know how often these strings are generated and what the normal size of such a script is... I guess it depends on the content that is being combined...   More generally I can say that heavy usage of the LOH will cause pockets of Free memory like this, and the amount of fragmentation you see over time depends on how well new strings fit into these pockets.  If you are allocating and deallocating the same size objects all the time it should be fine.  If the get continously larger you will see more fragmentation. 

I would just observe it over time and see if it gets really large.  I don't know how long you have been running at this point, but depending on the circumstances, ~13 MB doesn't seem extreme.   If it gets too bad then the options would be to reduce the size of the combined scripts or finding a way such that you cache the scripts or something so they don't get generated as often.  Not sure how that would be done though without researching more...

Q: Debugging managed code in IE

I have a .NET component that I've written using the 1.1 version of the framework. This component gets invoked by Internet Explorer via COM, like an ActiveX control. One of our testers is experiencing some hanging - it takes 3-4 minutes to load something up that comes up instantly on just about every other machine.

I grabbed a memory dump of the process while it was hanging, but nothing in the dump is considered "managed"... so there's not really much I can do with it. I know that it has loaded up managed code though. Have you ever attempted to debug iexplore.exe like this, and if so, would you be able to explain how you were able to do it?

My answer:

Yes, I have debugged winforms user controls in IE (see http://blogs.msdn.com/tess/archive/2008/02/19/high-memory-usage-with-usercontrols-in-ie-using-debug-diag.aspx).  If by "noting in the dump is considered managed" you mean that all threads are reporting

Thread 27
Not a managed thread.

then I think the simple answer is that either

a) you didn't get the dump at the time the process hung or
b) you are not hanging in managed code,  check out ~* kb to see if any of the threads are doing anything interesting in the native part of the stacks...  or
c) the "hang" is outside of the process, i.e. some network latency or similar

Are you perhaps running multiple queries to the same server so that you are trying to load up multiple usercontrols at once.  If I recall correctly you can run into blocking in those situations, but I don't remember the details...

Q: Getting to dependency properties with sos

I’m trying to debug a WPF application and I want to reach through GCRoot which of my object remain in heap and what of those It’s doesn’t begin disposed, and for this task I want to know the name of the control, but name is a Dependency Property (DP) so it’s a shared property, I can access to the instance of class DepenedecyProperty of Name property, but not to his value, because values are stores in other side. The only interesting filed was GlobalIndexCount. My question is, how access to get a value for a control stored in a DP?, Thank you.

My answer:

Unfortunately I don't know enough about dependency properties to know how they are stored in memory.  I do remember it being tricky though, the few times I have debugged WPF applications.  My advice would be create a small sample and hook up visual studio and stop at a place where you have access to the dependency property and use the watch window there to get a better feel for how it is laid out, and then you can bring that knowledge back and use it with windbg and sos in the "real" scenario.

Contact disclaimer

As I have mentioned before, there isn't enough time in the day to answer all the emails I get through the blog, so I usually only answer emails where I feel that the answer is something that might benefit many people. 

If you have an issue, and you're considering emailing me about it I should mention that you have a better chance of getting the question answered if you write it as a comment on a post it relates to.  If you're in an extreme hurry and/or have a very specific situation, you should definitely call support (see my Contacting Tess... post for more info)

Laters,

Tess

I was helping a colleague out with an OOM (OutOfMemory) situation he was dealing with. 

Problem description:

Their applications memory usage would grow over time until they finally ended up with an out of memory exception.

First debug:

They had gotten a memory dump when memory usage was really high 1.4 GB using debug diag and I opened it up in windbg.exe, loaded up sos (.loadby sos mscorwks) and ran !dumpheap -stat to get the content of the GC heaps.

The output above, showing the most memory consuming objects, tells us that there are pretty much two types of objects that consume most of the memory.  Data related items and UI related items. 

Notes about finding lots of UI objects on the heap

If you have followed my blog, you have probably noticed that I have spoken about this particular pattern before, with many UI related items, and that it is usually due to storing user controls in session or cache, and/or using static controls that where you set up event handlers in the page class to handle events for these static controls.  

Basically, anytime you store a control or a UI item in session scope, cache or static variables, you will also hold a reference to the page that it was created on, as well as any controls it has and any data that might be databound to any of the controls on the pages.  In other words, until the control goes out of scope, i.e. is removed from cache or session state, these objects will not be available for garbage collection.

Here are a few posts that I have written on the topic:

ASP.NET Memory: Thou shalt not store UI objects in cache or session scope
ASP.NET Quiz Answers: Does Page.Cache leak memory?
.NET Memory Leak Case Study: The Event Handlers That Made The Memory Baloon

Next debugging actions

When you see a lot of UI objects on the heap like this, the next step is to figure out why they are sticking around.  One of the things I will always do first in these cases is to look at aspx and ascx pages on the heap and !gcroot them to see where they are rooted, i.e. what is keeping them in memory.

In this case there were 1230 aspx pages on the heap,  in reality there should be approximately one per currently executing request, so this tells us that they are definitely staying longer than they should since I couldn't find a single thread executing a request when I printed out all the callstacks with ~* e !clrstack.

I gcrooted one of the pages to see why it is sticking around and found that it was stored in a static HybridDictionary...

And if I run !objsize on this Hybrid dictionary I find that it holds on to about 941 MB of data so this is certainly very interesting...

I have to add a small caveat here... if you !objsize something that contains an aspx page, your objsize will include the size of the cache since the page has an indirect reference to the cache. 

In this case though the cache is very small so most of the memory held up by this HybridDictionary is the pages itself.

Ok, so now we know that our issue is due to the fact that we have a lot of pages in memory, and they are sticking around in a static HybridDictionary.  The next step is to find out what this hybrid dictionary is and who is populating it with pages, and why...

To do this I dump out the HashTable+bucket[] that contains the page and search for the page address (6d67cb28) and the result was the entry displayed below

The page seems to be stored as the Key of this entry, so someone is populating a HybridDictionary with a key/value pair, where key=<the page>...

The value in this case is a ListDictionary

To figure out where this comes from, I saved out all the modules to disc using !for_each_module

!savemodule ${@#Base} f:\blog\modules\${@#ModuleName}.dll

as described in http://blogs.msdn.com/tess/archive/2008/01/10/using-reflector-to-search-through-code-and-resolve-net-issues.aspx. 

I loaded them all up in reflector, and did a string search for Ajax.NET.Prototype, which returned a method containing this string(AjaxPro.Utility.RegisterCommonAjax, in AjaxPro.dll)

Armed with this, I searched the internet for "AjaxPro memory leak HybridDictionary" and found http://www.ajaxpro.info/changes.txt which shows a list of changes in the AjaxPro library.  Of particular interest is a fix made in version 6.4.27.1

Version 6.4.27.1 (beta) - Fixed null values to DBNull.Value for System.Data.DataTable. - Fixed memory leak with HybridDictionary for JavaScript include rendering.

And the solution here was to upgrade to the latest version of AjaxPro.

About AjaxPro

Normally I don't write about 3rd party products, especially issues with 3rd party products, but I know that AjaxPro is a nice AJAX library that is used by quite a few of our customers so I hope this post is of general interest, as this issue is resolved in a later version of AjaxPro.   I also hope that the post can be of use for finding other similar issues outside of AjaxPro.

I should also mention that I am posting this with the permission of Michael Schwartz who developed AjaxPro, and I must say that I was extremely impressed with the openness in his response when I asked if it was ok to post about this.  His comment was, "feel free to write about it, I love to hear critics if there are any... to improve developement and/or fix bugs"

AjaxPro is now open source and can be downloaded from codeplex here http://www.codeplex.com/AjaxPro/. If you are interested in this you should also visit Michaels blog at http://weblogs.asp.net/mschwarz/

Laters,

Tess

I have probably mentioned this before, but I think it is worth mentioning again because of the frequency of this issue.

When debugging a crash, we usually get customers to use a crash rule in debug diag or to use adplus -crash to get memory dumps at the point of the crash.  Both of these attach to the process and gathers dumps when the process is shutting down, which is exactly what we want...

The problem is that very often we will get what I call "false-positive" dumps.  I.e. dumps when the process is shutting down, but not dumps of an actual crash, or at least not the shutdown we are trying to troubleshoot.

A typical characteristic of such a memory dump is that thread 0 is in the middle of a "normal shutdown"

By normal, I mean that the process is shutting down because the process is either being IISReset, or it is shutting recycled due to health monitoring settings. 

If it was an actual crash, you would typically see some 2nd chance exceptions occurring before the crash, generating 2nd chance exception dumps, and the process shutdown dump would only contain one thread (the last thread standing when the process is shut down).  Btw, this "last thread standing" is usually not thread 0 (the main thread), but rather some unsuspecting "bystander" thread that just happened to be the last thread hanging around at the crime scene, some thread that usually has nothing to do with the actual crash.

Another typical trait of a "false-positive" is that the process has been up for roundabout 20 minutes

Now, observant readers have probably figured out what is going on here... we get memory dumps when the process shuts down because of the idle timeout

By default, the worker process will shutdown after 1740 mins of processing (29 hrs), and/or when the process has been idle for 20 minutes.

So if either the process has been idle for 20 minutes, or the processing time is 29 hrs, the process will recycle and you will get a "crash" dump if you have a debugger attached. 

In summary, if you are trying to get dumps of a real crash, you need to disable these two settings in order to stop getting "false-positive" dumps, and get dumps on the real crash.

Laters,

Tess

From time to time we get issues with high memory and performance issues due to massive viewstate. I have talked about it before here, but I thought I'd show some techniques for finding out which pages have high viewstate.

If you look at a memroy dump of your process in windbg and notice that your large object heap is riddled with viewstate strings, that doesn't really tell you much, except for that you have some pages that have high viewstate, so the goose chase begings trying to find the source of these viewstate strings...

Btw, if the sentence above made no sense to you at all, you might want to check out the viewstate debugging article, to figure out how you identify that you have lots of large viewstate strings in the first place...

In this post I will show two ways of figuring out which page is generating the viewstate

1. Using the IIS logs

2. Inspecting the viewstate strings

To inspect the viewstate in the pages found in the IIS logs and the viewstate strings I am using Fritz Onion's viewstate decoder which you can download here

Getting the viewstate strings and identifying that we have large viewstate

The scenario here is usually that we have slow running pages and/or memory bloat in the asp.net process, and while looking at the memory we notice lots of large strings on the large object heap

SOS will not automatically print out the strings since this takes some time and clutters the image a bit, but we can print out all the large strings with a foreach command. 

In this example below I loop through all the strings over 85000 bytes (i.e. the ones on the large object heap), and then we print them with -nofields since we are only interested in the strings themselves.

I am just showing partial output to save some space, but what we see here is a string starting with /wEP which is typical for viewstate strings in 2.0.  In 1.1 they usually start with dDW.  Pretty much all the large strings in this dump look about the same, so from here we can tell that we have some pages emitting viewstate > 85000 bytes which means that each time the user views these pages they will have to download this data.

If the viewstate is large enough and we have enough concurrent users viewstate like this will cause both bandwidth issues and memory issues.

Identifying the pages with large viewstate in the IIS logs

The simplest way to identify which pages have large viewstate is to start logging Bytes Sent and Bytes Received in the IIS logs and go through the IIS logs to identify pages that have a lot of bytes sent (sc-bytes). 

Starting with the ones with the highest bytes sent you can then use Fitz Onion's Viewstate decoder to decode the viewstate by entering the URL, extracting the viewstate and decoding it...

In this example I have a page http://localhost/HighViewstate/Default.aspx that contains a gridview (grdProducts) and I have filled this up with 1000 rows, where each row has a product name (Product 1, Product 2, etc.)

When we decode it, we can see that my page has a viewstate of 164952 characters (~329904 bytes) which corresponds nicely to some of the strings on the LOH

Further, in the viewstate decoder (ControlState) we can see that we have one dictionary entry, grdProducts, so the viewstate seems to mostly pertain to this control... in the Viewstate box we can also see what the viewstate contains and in this case it is the different values in the datagrid (Product 443, Product 444 etc.). 

So based on this we can conclude that if we want to lower the amount of viewstate this page is emitting we would have to do something about the gridview, like removing the viewstate, filtering the data or similar.

Inspecting the viewstate strings from the dump

Inspecting the strings takes a lot longer and requires debugging, but it is also a more precise method. 

I would recommend that you start by inspecting the IIS logs, but if you already have a dump and have identified large viewstate strings, then this is the way to figure out where they came from.

For this we need to extract the whole string, plug it into the decoder and click Decode->.

If you run !do on the string, this will print out the string, but unfortunately it will only print out a part of the string so we need to figure out a way to get the full string so that we can plug it into the viewstate decoder.

Looking at this string for example

We can see that the size is 329922 bytes or 0x508c2 hex bytes, and we can print out the string using du <address> <address>+size, or to be more specific we would print it out using du <address>+0xc <address>+size because the actual string starts at an offset of 0xc.   du means dump unicode, i.e. du <start> <end> will print the contents between <start> and <end> in unicode, which is what we want.

ok, so this gives us the string, and we can copy and plug it into the viewstate decoder if it wasn't for the fact that we would have to manipulate the output, removing the first column and the double quotes which is a bit of a hassle.

To get a clean string, we can execute the same command, and encapsulate it in a .foreach so that we skip the first column by adding /pS 1 /ps 1

And now, finally we have a clean string that we can copy into the Viewstate String: textbox in the viewstate decoder. When we decode it we will get a very similar output to the one we got when decoding viewstate from an URL, and based on the contents of the viewstate (i.e. finding out that it belongs to grdProducts, and has the contents Product 1, Product 2 etc. ) we can narrow down the page that it belongs to.

And that is pretty much all there is to it...  

Laters,

Tess

When you have to pass an object back and forth between processes or application domains you have to serialize it into some type of stream that can be understood by both the client and the server.  

The more complex and big the object gets the more expensive it is to serialize, both CPU wise and memory wise, and if the object is big and complex enough you can easily run into out of memory exceptions during the actual serialization process... and that is exactly what happened to one of my customers... 

They had to pass very large datasets back and forth between the UI layer and the datalayer and these datasets could easily get up to a couple of hundred MB in size.  When they passed the datasets back they would get OutOfMemory Exceptions in stacks like this one...  in other words they would get OOMs while serializing the dataset passing it back to the client...

My gut feeling was that they were SOL. I know that serialization is very memory expensive and that the resulting serialized xml strings can get enormous so I wasn't very surprised, especially knowing how large their datasets were.  

I am not a data access guru, but I have seen this type of issue enough times that I knew what the recommendation should be.

1. Re-think the architecture... what are you using these datasets for? who will be browsing through 100s of MBs of data anyways?  (and this still holds true,  in most cases where there is this much data involved only a very small part of it is needed and if that is the case, then only a very small piece of the data should be handled, i.e. filter out what you need and leave the rest)

2. Re-consider passing this data through remoting/webservices/out-of-proc session state or whatever it might be.  Once you start serializing and deserializing this amount of data you are threading on thin ice when it comes to the scalability of your application, both performance and memory wise.  Again, this still holds true, if the dataset itself is 100 MB you will only be able to have a handful of concurrent requests before you run out of memory for the datasets alone.

3. If you really really really need this much data and this architecture you need to start thinking about moving to 64 bit, but even there you need to be careful so that you have enough RAM and disc space to back up the memory you're using, and still you need to be careful, because the more memory you use, the longer it will take to perform full garbage collections.

We discussed a couple of options like bringing back partial datasets, chunking it up, but still most of it was a no-go.

Debugging

I created a very small remoting sample with just one method that returns a very large dataset (you can find the code for the sample at the bottom of this post...  just to see how much memory we were actually using for the serialization (the dataset itself was 102 MB).

I attached to the remoting server with windbg and loaded up sos (.loadby sos mscorwks) and then I set a breakpoint on mscorwks!WKS::gc_heap::allocate_large_object so that I could record the size of the allocation (?@ebx) and the stack (!clrstack) everytime we allocated a large object  (I figured this was enough for a rough estimate)

0:004> x mscorwks!WKS*allocate_large*
79ef212d mscorwks!WKS::gc_heap::allocate_large_object = <no type information>
0:004> bp 79ef212d "?@ebx;!clrstack;g"

Low and behold, the last attempted allocation before the OOM was a whooping 1 142 400 418 bytes (~1 GB!!!! for a 100 MB dataset)

When you try to allocate an object like that it needs to be allocated in one chunk.  Since it is larger than the size of the LOH segment we will try to create a segment the size of the object, and in my case I just didn't have 1 GB of free space in my virtual memory in one large chunk, so the allocation fails with an OOM.

Fine,  what did I learn from this?  well, I just confirmed what I already knew, that serialization is very expensive.  In fact in my case I had to allocate 1 GB to serialize 100 MB so a factor of 10, and that is not even all...  if I would have been successful in allocating this, I would still have had to allocate some more intermediate strings in the neighborhood of a couple of hundred MBs, so all in all it seemed like an insurmountable task to serialize a dataset this big.

Solutions

I mentioned a few earlier, which basically include, don't serialize datasets this big, and if you must, then go to 64-bit.

I remembered though, that on 1.1 there was an article that had some suggestions on how to optimize the serialization by creating dataset surrogates, i.e. wrapper classes that performed their own serialization rather than using the standard one that remoting uses.  http://support.microsoft.com/kb/829740

I knew things had changed in 2.0 so that article was no longer applicable, but I didn't really know what it had changed to, so I went on an internet search and found this article that turned out to explain a loot of good stuff about serialization of datasets.

http://msdn.microsoft.com/en-us/magazine/cc163911.aspx

The article suggests that you should change the serialization method if you need to remote very large datasets.  I did this by adding one single line to the remoting server, before returning the dataset

ds.RemotingFormat = SerializationFormat.Binary;

Then I re-ran the test and didn't get the OOM.  Not only that, but when I ran it through the debugger with the same breakpoint... instead of the 1 GB allocation, I ended up with 5 * 240 k allocations and one 225 k allocation used for the serialization (not counting any non-large objects).  Memory wise, that is an improvement of 100 000% for one extra line in your code, that's a little bit hard to beat:)   

Have a good one,

Tess

Sample code used for this post

Server: