Home > IIS Stories > .NET Debugging #3/3 – Finding ASP.NET pages of High CPU Problems

.NET Debugging #3/3 – Finding ASP.NET pages of High CPU Problems

Pre-readings :
ASP.NET Threads – Thread Parameters in IIS Worker Processes
https://fullsocrates.wordpress.com/2013/02/28/asp-net-threads-thread-parameters-in-iis-worker-processes-2/
.NET Debugging #1/3 – What are in a memory dump
https://fullsocrates.wordpress.com/2013/07/15/net-debugging-13-what-are-in-a-memory-dump/

.NET Debugging #2/3 – Checking ASPx Pages running in IIS Proces
https://fullsocrates.wordpress.com/2013/07/21/net-debugging-23-checking-aspx-pages-running-in-iis-process/

 

High CPU Utilization Problems

 

In any version of IIS, & .NET framework, high CPU hang problems can happen, because they’re more about disigning ASP.NET applications, patterns of handling requests & data, rather than any bugs of Windows, or any magics in web servers.

Basically, CPU is a processor, which can be just a device on a mainboard, people may not need to worry about hard working of the device, and we just need to let CPU work effectively.

In a mission critical service, or public web sites can have more concerns for the high CPU utilization, and it’s because there’re impacts on their web service, such as delayed response from web server, hard to ask more patience, or blank screen for a while in a brower of users who’re about to leave the web site, to buy something in other company’s web sites.

The way how we can identify ‘High CPU Hang’ is anther story. It’s required to use ‘PerfMon’ or any performance data collectors, and analyze data to check if processors are bottleneck or not, and  this article covers .NET debugging tips after idenitfying High CPU hang problem.

 

Sample Codes to use

 

The following code is to cause High CPU hang problem. It is getting hard to cause the problem, because of much improvements of H/W & .NET. It’s used to be easy, just concatenating some strings could make it, you may need more efforts to make IIS unresponsive, when there’re more processors.

HighCPU.aspx.cs is designed to create 2 threads, and start the threads to compute numbers continuously for 30 seconds.

HighCPU.aspx, HighCPU.aspx.cs


using System.Threading;

protected void Page_Load(object sender, EventArgs e)
{
    DateTime dtNow = DateTime.Now;

    Response.Buffer = false;
    Response.Write("<br> This page causes ‘High CPU Problem’ for 80 seconds at least.");

    Thread workerThread1 = new Thread(Worker1Thread);
    Thread workerThread2 = new Thread(Worker2Thread);

    _shouldStop = false;

    workerThread1.Start();
    workerThread2.Start();

    Thread.Sleep(30000);

    RequestStop();
    workerThread1.Join();
    workerThread2.Join();

    Response.Write("<br>Elapsed time = " + DateTime.Now.Subtract(dtNow).ToString());
}

public void Worker1Thread()
{
    double i = 123;
    double j = 123;

    while (!_shouldStop)
    {
        i = i * j;
        i = i / j;
    }
}

public void Worker2Thread()
{
    double i = 123;
    double j = 123;

    while (!_shouldStop)
    {
        i = i * j;
        i = i / j;
    }
}

public void RequestStop()
{
    _shouldStop = true;
}

private volatile bool _shouldStop;

// END OF HIGHCPU.ASPX

 

So, the above is far from any decent code, but readability is guaranteed. 🙂

Here’s a sample code(longtime.aspx), to cause long time running with very less CPU utilization. In my test, I’m going to send requests for highcpu.aspx, and longtime.aspx both.

<%@ Import Namespace="System.Threading" %>
<%
    Response.Write (DateTime.Now)

    Thread.Sleep(30000)
    Response.Write("<br>30 seconds passed<br>")

    Response.Write(DateTime.Now)
%>

 

Under High CPU Hang

 

I’m going to call both requests above, and show you how we identify the exact page that caused High CPU hang, in a memory dump by using .NET debugging skills.

image

As you can notice, ‘longtime.aspx’ doesn’t cause high CPU hang, but I’m going to call them to check if we can differentiate a page that caused high CPU hang problem, with other innocent asp.net applications.

image

So, as soon as my browser calls ‘highcpu.aspx’, and ‘longtime.aspx’, %CPU becomes about 50%+, and some of processors started working hard. Processor works with threads, so the sample doesn’t cause CPU 100%(total) hang, as it created 2 threads to compute numbers for a while.

It’s time to collect memory dump files for W3WP process using the task manager, as mentioned in the previous post, by right-click  ‘Create dump file’ in the process list. This time, it’s recommended to collect w3wp memory dump at leat 2 times, and the reason will be explained later. So, I collected dump files 2 times with about 20 seconds interval.

 

Reading W3WP memory dump using WinDBG

 

Now, run WinDBG x64, open the first dump file(w3wp.1st.dmp), and set symbol path as below,

image

and, load sos, located in Microsoft .NET Framework/versions that being used.

The first command after loading sos, is !threadpool

[w3wp.1st.dmp]

image

The output of !threadpool command displays ‘CPU utilization: 52%’ as above. Someone may think this’s not high CPU hang conditions, but if you review all the given conditions, such as – there’re 4 processors, and just run a single page with 2 threads, – this can be a problem anyway. To make this clear, dump files have been collected 2 times.

‘!runaway’ command can display CPU time spent for eachc thread, so run ‘!runaway’ command, and it’s required to compare output of !threadpool & !runaway command from 2 dump files as follows,

image

The result shows you output of debugger commands, and we can find that %CPU is still 52% in the second dump, collected after (about)20 seconds from the first one. More importantly, The thread #27, #28 are consuming most processor time, and exactly same threads have consumed more processor time after 20 seconds.

image

[Now go to #28 thread, run !clrstack, it shows ‘HighCPU.cs’, ThreadStart(), Worker2Thread()]

This debugging task is handling w3wp process dump which has threadpools for ASP.NET applications, or ASP applications. (This case, high CPU problem is caused by user-created threads.) In order to identify actual ASPx that caused high CPU, we need this kind of information that includes ‘growth amount of CPU time’ for each thread. Otherwise, we may miss an actual target aspx, because any worker threads are not dedicated to run a specific web application.

Therefore, the debugger may indicate a wrong & innocent aspx if we collect a dump just once, because a worker thread may run highcpu.aspx, increased CPU time in the thread, then the thread is running any lowcpu.aspx – dump file can be collected at this moment, and say ‘oh, lowcpu.aspx in #THREAD_ID, was consuming most CPU time’.

By collecting 2, 3, more times of memory dump, we can minimize possibility to make wrong anlaysis.

image

To check more details in threads of #27,#28, !clrstack, and !dso (dump stack object) commands are very useful to start with. The above screen shows results of !clrstack, and !dso command in #27 thread. Sometimes, !dso says how’s going on in the thread. The following commands depend on what you want to investigate.

In addition, it’s not easy to find a thread for ‘longtime.aspx’, because CPU Time for each thread doesn’t give us any clue, it’s in somewhere of a worker thread, as follows.

image
[longtime.aspx is being executed in #18 thread, without spending much CPU time]

You can also what are running in the thread, not in stack information, there’re more ways. Anyway, this post is already too long…

 

What if the thread is not related with ASP.NET

 

After identifying a CPU consumer thread, sometimes it can be a just native, or GC thread. In terms of GC performance, I’d like to cover this topic in my next post. In most cases, GC is not guilty, however, GC performance topic can be useful, and long story.

 

More Information of High CPU Troubleshooting

 

Thank you WinDBG & WinDGB developers, you saved my life many times, and let me introduce more tips to work with high CPU scenarios,

!runaway 3

image

‘!runaway 3’ can show you Kernel mode time too. High CPU problem is not only caused by user-mode, and in IIS, if there’re too many LDAP queries, or calling Kernel routines, ‘User Mode Time’ doesn’t explain all.

lm, lmvm [module_name]

image

When I want to review loaded modules, or invetigate a module, lm is the command to start, including managed modules.

 

In Summary,

 

High CPU hang issues in IIS/ASP.NET, can be handled by using WinDBG & .NET debugging skills, and the first step is indentifying ‘High CPU Porblem’ itself – problem definition, and collecting memory dumps enough times to avoid misconclusion.

WinDBG with SOS extension, provides !threadpool, and !runaway commands to see cumulative CPU time, consumed by the thread. !threadpool shows total %CPU, and !runaway shows CPU spent time by individual proessor.

High CPU hang issues can be caused by unexpected components, such as kernel drivers, or extreme number of calls repeatly. Sometimes, limited loop becomes unlimited loop because of exceptions, or returns from external resource – file, a DB table. GC also can be a reason of High CPU, which can be measured by %Time in GC of ‘.NET CLR Memory’ performance object.

Good luck!

Advertisements
Categories: IIS Stories
  1. No comments yet.
  1. No trackbacks yet.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out /  Change )

Google+ photo

You are commenting using your Google+ account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

Connecting to %s

%d bloggers like this: