Clarity, Technology, and Solving Problems | PracticeThis.com
WP7 App with Key Windows Azure resources – Slides, Videos, How-To’s, and T-shooting – for quick consumption on the go.
A customer complained that his ASP.NET web application gets slow periodically. It happens at random times, the system just gets slow then after few minutes it gets back on track with normal response times.
One of the reasons for such behavior is an AppPool default recycling policy set in IIS.
The default recycling policy for application application pool is 29 hours. Both IIS 6.0 and IIS 7.
It means that every 1740 minutes the application pool recycled. 1740 minutes means 29 hours. 29 hours means randomness.
To make sure you are dealing with recycling (there are few more reasons I will be discussing in the next posts) one needs to correlate IIS recycle events in Windows Event log with slowness of the pages in IIS log.
Start with Windows Event log. Go to System Event Log and filter events with W3SVC as a source. Look for recycle events with id of 1074:
Notice the time the recycle occurred.
Go to IIS logs and filter out the resources that took significantly long. One way to look into the IIS logs is using Excel as outlined here - Identify ASP.NET, Web Services, And WCF Performance Issues By Examining IIS Logs. Another way is using LogParser as outlined here (via Tess) - Using LogParser 2.2 to Parse IIS Logs and Other Logs.
Notice time-taken is pretty lengthy, around 30 seconds. Notice the time it is taken. Now look at the times that the Event log captured 1074 events – it is 2 hours diff. It is because IIS logs events using GMT and Windows Event log is time zone sensitive. I live in GMT+2 time zone. So the times are correlated.
Remove IIS recycling default policy. I once heard someone saying it is training wheels. If your app pretends to be stable then you do not need recycling at all – of any kind. Just remove it all. If you are using recycle there are potentially two reasons, actually one – you have problematic application that misbehaves. It’s either under your control to fix it by changing the code or out of your your control when you buy an app that you cannot fix. Ask for a fix from the vendor. It might be also a good time to review your capacity plan. In any case – recycling is a workaround and not the solution.
A customer complained that his web application gets slow each morning at specific times. The rest of the day the application was providing satisfactory performance in terms of response time.
The assumption was that at that times all employees sign in creating unexpectedly high traffic which caused the slow response
We needed to verify it. We needed to build simple histogram that would show the distribution of hits throughout the day. This is what we have done to achieve this.
Using Log Parser we prepared IIS logs. By “prepared” I mean we consolidated multiple logs into single one. We also removed unnecessary fields making the resulting file smaller. In fact, we needed only time field. Here is the sample LogParser query that retrieves only time for each entry in the log and stores it in Time.log file. Here I assume that all the log files are named ex<something>.log:
LogParser –i :IISW3C "SELECT time FROM ex*.log" -q >Time.log
While it is possible to write a more complex grouping query including creating graphs using LogParser but I just think Excel is perfect tool to create graphs, eh? This is what we have done:
Sorry I made you read thus far. Can’t help – love Excel pivot functionality ;)
You could use this simple LogParser query to get same results without Excel:
LogParser –i :IISW3C "SELECT count(*) as hits, TO_STRING (time,'hh') as hour FROM ex*.log group by hour"
The result would look similar to this:
hits hour ------ ---- 111527 11 114283 12 27721 13
Following is a list of performance counters I am usually taking to spot low hanging fruits when measuring ASP.NET performance:
\.Processor\%Processor Time \.NET CLR Memory(*)\Allocated Bytes/sec \.NET CLR Memory(*)\% Time in GC \.NET CLR Exceptions(*)\# of Exceps Thrown / sec \.NET CLR Loading(*)\Current Assemblies
\.NET CLR LocksAndThreads(*)\Contention Rate / sec \.NET CLR LocksAndThreads(*)\Current Queue Length \ASP.NET\Requests Queued \ASP.NET\Request Wait Time \ASP.NET\Requests Current \ASP.NET Applications\Requests In Application Queue \ASP.NET Applications\Pipeline Instance Count \ASP.NET Applications\Requests Executing \ASP.NET Applications\Requests/Sec \Web Service\Current ISAPI Extension Requests
\ASP.NET\Request Execution Time
Detailed explanation about each counter and its significance can be found here: Chapter 15 — Measuring .NET Application Performance
I particularly love the following diagram from the guide. The diagram helps brainstorming while identifying root cause of the performance issues identified using the counters: