Identifying problems in ASP classic application - Part 1
Last week I was in a customer that was experiencing a sort of problems in his website. It was a very complex situation, with an ASP-classic application using several bad practices in his code.
However, the major problem is that customer has no idea about errors in his application. To him, the problem was caused by Microsoft SQL Server hitting 100% CPU usage.
A short exam of IIS and event logs shown the problem was in the application code and not in IIS or even SQL. Of course, a log analysis is not a so simple task to do if you don't have the appropriate tool.
Anytime I've to do this kind of task, I use Microsoft LogParser. There are a lot other tools that could be used to achieve this, but Logparser really rocks! In special I link the fact you can use "SQL-like" syntax to obtain almost any information from several kinds of logs.
So, going to the real thing, a simple logparser query used to read and process an IIS W3C Extended Log file looking for errors registered is shown below:
logparser "select cs-uri-stem, sc-status,sc-win32-status,COUNT(cs-uri-stem) from <IIS_LOG_FILE.LOG> to errors.csv where sc-status >= 400 GROUP BY cs-uri-stem,sc-status,sc-win32-status ORDER BY COUNT(cs-uri-stem) DESC" -o:CSV
This gave me a lot of URLs with 500 errors. From this point, I also had started checking other things and also had found several errors in application event log. Looking at application event log I'd also found several entries similar to:
8/20/2007 4:49:39 PM Active Server Pages Warning None 9 N/A SERVER_01 Warning: 500 Server Error. .
8/20/2007 4:49:25 PM Active Server Pages Warning None 9 N/A SERVER_01 Warning: File /search_payment.asp Line 29 Type mismatch: 'fValidateC'. .
8/20/2007 4:48:58 PM Active Server Pages Warning None 9 N/A SERVER_01 Warning: File /basket_001.asp Line 33 Type mismatch: 'oBasket.Item(...)'. .
8/20/2007 4:48:48 PM Active Server Pages Warning None 9 N/A SERVER_01 Warning: File /finalizebuy01_.asp Line 304 Type mismatch: 'oBasket.Item(...)'. .
[Page names, server names and other sensitive information was changed to prevent customer identification]
At this point I'd realized the problem was in their application. So, I'd two approaches that could be used to identify the problem:
a) execute a dynamic analysis, I mean, getting a memory dump of process and analyzing it (or a set of memory dumps).
b) execute a static analysis, I mean, a code review.
My first idea was get memory dumps when error 500 happens; When doing this, the first thing to check (before get the dump) is the possible size of dump file. It's very easy to do this: just check the object Process\Virtual Bytes in PerfMon for the process running the application code (in this case, W3WP.exe); Ok, and how can I know what is the instance of W3WP.exe if I have several ones? Also, very easy: at command prompt, just call the iisapp.vbs command. The result will be a list with Application Pools names and correspondent Worker Process PIDs.
When I checked this information, I found a impressive result: 1.8Gb of VM usage for the process hosting the application; never had seen this before. Obviously there was a problem there, and get a memory dump was not a good option at this point (why? because the dump file would have 1.8Gb or more in size, and this could take a loooong time to be generated).
After some discussion with customer, I'd opted to executed the second option, also because the system is very critical and get a memory dump obviously might cause an unacceptable outage to them (Later I'll post other entry about this code review where I'd realized why so many VM memory was in use).
|
Lessons from this post:
a) Look at IIS Logs for errors 500; use MS Logparser to do it.
b) Look at Application event logs for errors/warnings in source Active Server Pages. Also you can use MS LogParser;
c) Before get a memory dump, check the VM memory usage of Worker Process; |
to be continued...
