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.
In this post I will share with you how to automate code review when searching MSIL for common performance and security anti-patterns.
You are an application performance/security consultant who’s been asked to review a large application for common security and performance anti-patterns. You are given no time and no source code. What you are given is 250 dll’s. What do you do?
It is easy to reverse engineer compiled .Net binaries. .Net SDK ships with ILDASM – disassembler that dumps intermediate language (MSIL) out of the assemblies into text file. The resulting file is not really human readable (although there are few individuals out there who can actually really read it and understand), but it is good enough to perform text searches for several patterns. To perform text searches one would use findstr command. Here are few examples:
Find strings in resulted MSIL text file: Ildasm.exe yourcomponent.dll /text | findstr ldstr
Find string constants in resulted MSIL text file: Ildasm.exe yourcomponent.dll /text | findstr /C:"literal string"
Find boxing/unboxing in resulted MSIL text file:: Ildasm.exe yourcomponent.dll /text | findstr box Ildasm.exe yourcomponent.dll /text | findstr unbox
The searches above can help identifying either security or performance issues.
The question here is how to automate the process for 250 dll’s.
The following are the steps we take to automate the search:
/A:-D means no directories, files only. /S means search subfolders. It is useful if you have dll’s in subfolders. /B means bare format, no headers, only file names.
DIR /A:-D /S /B *.dll >C:\DllsList.txt
Ok, now we have the text file – DllsList.txt – with the list of dll’s we want to inspect.
Now we create a vbs file that contains a script to build batch file. This batch includes search commands for each dll in the list we just created. In the sample below we create a batch file that will look for strings – ldstr . Substitute this search criteria to your needs.
=====VBS FILE START====
'ILDAMS FILE PATH ildasmFilePath = """C:\Ildasm.exe"""
'ASSEMBLIES LIST TEXT FILE assembliesFileList = "DllsList.txt"
'FINDSTR FILE PATH findStrPath = "C:\Windows\System32\findstr.exe"
Set fso = CreateObject("Scripting.FileSystemObject")
'OPEN ASSEMBLIES LIST FILE FOR READ Set assembliesList = fso.OpenTextFile(assembliesFileList, 1, False)
'OPEN TARGET BATCH FILE FOR WRITE Set batchFile = fso.OpenTextFile(assembliesFileList & ".bat", 2, True)
'LOOP THROUGH ASSEMBLIES LIST AND ADD LINES TO BATCH FILE
Do While assembliesList.AtEndOfStream <> True
assemblyPath = assembliesList.ReadLine stringToWrite = ildasmFilePath & " """ & assemblyPath & " "" /text | findstr ldstr >""" & assemblyPath & ".Strings.txt"""
batchFile.WriteLine stringToWrite ' msdbox stringToWrite
Set assembliesList = Nothing
=====VBS FILE END====
The result is a vbs file ready to be used. Double clicking on the vbs file creates a batch file with a similar name. Open the batch file and review the contents. It should look similar to this:
Now that we created the batch file – let’s run it. The result would be a bunch of text files with search criteria results in it. All that is left is inspect the files. For example, in case of security we’d look for a patterns outlined here:
In case of performance review we’d just go straight to the source code of the identified dll’s to look for massive boxing/unboxing which usually happens when we use general purpose collections.
To make the process of inspection easier and faster use instant search available in Outlook 2007 as it is outlined here:
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: