If broken it is, fix it you should

Using the powers of the debugger to solve the problems of the world - and a bag of chips    by Tess Ferrandez, ASP.NET Escalation Engineer (Microsoft)

Using VSTS Test and Profilers to troubleshoot performance issues (low cpu hang)

Using VSTS Test and Profilers to troubleshoot performance issues (low cpu hang)

  • Comments 18

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.

RunTest

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.

image LoadCPU

Adding a performance session

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

performancesession

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

PerfSession 

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

In the output window you should see messages like

Profiler started
OnTestRunStarted(7b3e3588-fea6-4172-94a9-683b3a43d3ce)
Instrumentation Succeeded:C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\Temporary ASP.NET Files\buggybits\b27906cc\f5f91899\App_Code.sveh1hhn.dll
Instrumentation Succeeded:C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\Temporary ASP.NET Files\buggybits\b27906cc\f5f91899\App_global.asax.-r1dattg.dll
Successfully attached to process: 6476
Instrumentation Succeeded:C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\Temporary ASP.NET Files\buggybits\b27906cc\f5f91899\App_Web_prgsmyy7.dll
Instrumentation Succeeded:C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\Temporary ASP.NET Files\buggybits\b27906cc\f5f91899\App_Web_nomnlqw7.dll

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

PerfReportSummary-Featured

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.  

MonitorEnter

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…

GetFeaturedProducts

 

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

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

  • Web YUI 2.6.0 Released Practical Functional JavaScript: Code Samples Removing unused CSS Classes from

  • Somehow I've totally overlooked this functionality and have been only concentrating on page/transaction response time and metrics collection.

    This is pretty sweet!

  • Very Useful Article, Thanks!

    Me and my team tries to make a collection of really useful asp.net articles, so can We have your permission to include your asp.net products in our catalog(title, short info, etc.) ?

    Of course, you can add your articles to the catalog using our submit form:

    http://www.aspnetsource.com/articles/SubmitNewArticle.aspx

    Thank you in advance,

    Tihomir Ivanov

    AspNetSource's Team

  • as long as you link to the original post you are more than welcome to include it anywhere you like

  • Following my post about how to troubleshoot a low CPU performance issue with VSTS Test, I will now do

  • Tess Ferrandez wrote a couple of articles recently that extend a series of debugging labs she created

  • Hello Tess .. Firstly Thanks for this article.. i have problem with Performance Session..

    When i tried to do this i got an error :

    The web site could not be configured correctly; getting ASP.NET process information failed. Requesting 'http://localhost:2160/Web/VSEnterpriseHelper.axd' returned an error: The information returned is invalid.

    Do you have any idea ?

  • Ok i have fixed the error :

    Adding the following line to Web.config file :

    <authorization>

         <!--<deny users="?" /> -->

         <allow users="*"/>

    </authorization>

  • interesting, thanks for the update

  • i have again a problem :

    The web.config file X:\Web\web.config has been changed and backup information was lost.

    Do you have any idea ?

  • Ok. i have resolved my own problem again:

    I think this problem occures working with Source Safe.. When i did get lastest the Project, problem was solved...

  • And again changed Web.config :

    <location path="VSEnterpriseHelper.axd">

     <system.web>

       <authorization>

         <allow users="*"/>

       </authorization>

     </system.web>

    </location>

    this is right solution :)

  • Here is a very good ariticle about using performance/profiling tools in Visual Studio Team Suite to troubleshoot

  • Just a placeholder for some good ASP.NET performance tuning and troubleshooting resources. Learning Links:

  • Visual Studio Team System for Testers Content Index for Web Tests and Load Tests Getting Started Online

Page 1 of 2 (18 items) 12
Leave a Comment
  • Please add 7 and 4 and type the answer here:
  • Post