开发者

What is consuming over 65% of time in an ASP.NET application?

开发者 https://www.devze.com 2023-03-27 00:03 出处:网络
I have an .Net Framework 4.0, ASP.NET, ASP.NET MVC 3 web application hosted on a Windows 7 / IIS 7.5. IIS logging is enabled on this machine and set to log in W3C mode.

I have an .Net Framework 4.0, ASP.NET, ASP.NET MVC 3 web application hosted on a Windows 7 / IIS 7.5. IIS logging is enabled on this machine and set to log in W3C mode.

The application is compiled by using the Release configuration and has been deployed to IIS with <compilation debug='false' attribute set explicitly. The Web.config specifies the use of SQL Server based session state.

I have added the following statements in Global.asax in BeginRequest and EndRequest events respectively. The results i.e. "sw.Elapsed.TotalMilliseconds" are getting stored in an Application level list of values. I dump these values out via a debug page and get an average of the same.

// in BeginRequest
HttpContext.Current.Items.Add("RequestStartEnd", System.Diagnostics.Stopwatch.StartNew());

// in EndRequest
var sw = (System.Diagnostics.Stopwatch)HttpContext.Current.Items["RequestStartEnd"];
sw.Stop();

I have created a load test which runs a single request against this application with a concurrent user load of 20 users. The test is run in Visual Studio 2010 Ultimate edition.

After running the load test, I am getting an average time-taken as recorded by the stopwatch as 681 milliseconds.The average time-taken as per IIS for these requests (I cleaned out all logs before running the load test) is 2121 milliseconds. The average time-taken as per IIS tallys with the value shown in Visual Studio load test report.

The stopwatch time-taken only accounts for 32% of time-taken as reported by IIS logs / Visual Studio. Where does the other 68% time go?

Update 1: I set the session state to InProc and re-ran the load test. In this scenario the difference between the average time reported by stopwatch and average time-taken reported by IIS logs grew to more than 70%!!! Where is all that time going?

Update 2: @Peter - I tried out the failed request tracing by putting开发者_JS百科 a trace rule to log on status code of 200. Next, I ran the load test with 20 concurrent users for approx 1.5 minutes. Went through last 50 trace files and found that the "Time Taken" field in that report had range of 750ms to 1300ms. The Visual Studio report showed avg. time taken as 2300ms. In the report, using the compact view, I see that the time taken changes between the following transitions (1) AspNetStart -> AspNetAppDomainEnter (2) ManagedPipelineHandler-start ManagedPipelineHandler-end. The (2) item is probably my application's code. Still there is a big difference between max of time-taken as per failed request logs i.e. 1300ms and the avg. time-taken as shown by Visual Studio 2300ms. How to find accounting for that? Thanks for this great tip though!


How long are you running your load test for? If you're running it under windows 7 you may get different results than under a windows server as well. You could be having issues with getting threads allocated to the thread pool under burst loads. .Net will immediately allocate threads up to the thread pool min and then slowly allocate up to the thread pool max. I believe the default settings for client OS's are different than for server OS's. It may be on a client OS the default min thread setting is equal to the number of cores on your machine, meaning that .net will then slowly allocate more threads to meet your burst load.

A simple check would be to let your load test run longer and see if the gap between your 2 measurements narrows.


There is a better way to look into the internals of your app, by using "Failed Request Tracing Rules"

http://learn.iis.net/page.aspx/266/troubleshooting-failed-requests-using-tracing-in-iis-7/

With that you can follow exactly what you app is doing in IIS


I would suggest looking into MvcMiniProfiler. It's a NuGet package you could add and wire in (almost effortlessly) that really breaks down the execution times of various points in your MVC app. You could see a live view of each request and where any bottlenecks reside.

More info:

  • http://code.google.com/p/mvc-mini-profiler/
  • http://www.hanselman.com/blog/NuGetPackageOfTheWeek9ASPNETMiniProfilerFromStackExchangeRocksYourWorld.aspx
  • http://www.nuget.org/List/Packages/MiniProfiler


Its most likely a combination of the Managed Pipeline overhead and your network (even localhost or 127.0.0.1) is probably where the "lost" time can be accounted for.

  1. You mention that the IIS logs tally with your Visual Studio load test figures - both of those involve the network stack and the managed pipleline.
  2. Your stopwatch code only executes inside the ASP.NET context (just before ASP.NET execution begins and just before it ends), and does not take into account the IIS overhead of processing a TCP network request, parsing HTTP-headers for both the request and response and transmission time through the managed pipeline and TCP stack.
  3. [EDIT] The proportion is exaggerated even more if your ASP.NET page execution time is really fast, e.g. it does not consume a lot of CPU relative to the rest of the TCP stack and managed pipeline that marshals the HTTP request for you


if you are having issues with long load times it may be related to several things if you have a high number of IO operations it can affect this if you are doing database queries with an orm try profiling your sql statements either in vs with a sql profiler or in sql servers built in profiler if you are getting alot of individual querys you may want to consider using some includes in you linq queries to bundle up some of your data into single queries

you may also want to consider want to consider using async controllers to improve response times if you have alot of IO operations so your application isnt continuously waiting for each io operation to complete see wintellect.com/CS/blogs/jprosise/archive/2010/03/29/…

there also better solutions out there for logging than the iis logging as it is a fairly old component you may want to take a look at log4net for more general logging or elmah for logging errors and exceptions as these solutions can bundle up a bunch of log entries and write several in a single operation also improving IO performance

0

精彩评论

暂无评论...
验证码 换一张
取 消

关注公众号