The other day we were getting complaints from users on one of our legacy asp application running with SQL server as the backend database. The users saw slowness across all the pages and upon further investigation i was able to replicate the slowness. However the slow performance was random and sometimes the app was behaving as usual.
On inspecting the server, i could see that the IIS process (w3wp.exe on your task manager) was consuming a lot of resources ( almost 50% of CPU when the users experienced slowness). This led me to believe that something in the legacy code was causing the trouble. But then again, this same code has been running fine for quite some time and I was not aware of any new code changes.
Perhaps, over a period of time, data in the sql server db has changed that might have caused an inefficient execution plan? The load on the db server didnt particularly concern me, though there were very small spikes during the time when IIS cpu was up.
So my first step was to use Failed Request Tracing in IIS and see whether it shows something right out of the box.
If you have not used FRT, then this blog post explains how to use failed request tracing and how to set up tracing when a request takes more time than usual. In my case some requests were taking more than 20 secs for a website when it should have returned back in milliseconds.
Unfortunately for me, the log file didnt immediately give me back the results i had hoped. I was getting this.
The default log file size is 500KB and so that wasnt enough to debug my issue. So i decided to increase the log file size and you can do that by doing the following . I set the size to 1MB
cd /d "%windir%\system32\inetsrv"
appcmd set config /section:sites -siteDefaults.traceFailedRequestsLogging.maxLogFileSizeKB:1024
After the size increase, i still got the same message. The timing information in the trace file didnt reveal anything as well, as the operations were all in milliseconds. So I kept increasing the size till 10MB and still was getting the log file max size.
This indirectly helped me to realize that the asp code was executing something big that even the 10MB trace file wasnt able to capture. (I could have tried LogParser utility to see whether there was any particular page that was causing the issue, but users issues were not restricted to a single page. They saw all across. ) I had already looked at the sql server activity monitor and ran the sys.dm_exec_requests and sys.sysprocesses and saw that the last statement that was executed was a call to particular stored procedure (when a slowness by a particular user was reported). I had already tested the procedure and it was returning data within milliseconds.
I then decided to use the sql server profiler to see the statements that were getting executed hoping that it might give me a clue. Since i was using SQL server express edition, it didnt come with a sql server profiler. On further reading i found a simple open source tool Express Profiler.
Bingo i saw one statement that was returning huge chunks of data than normal (the timing wasnt an issue,the statement was still returning in < 1 sec) . The statement was a call to the sql server stored procedure with null parameters. The stored procedure should return only one row of data. But for null param, it was returning over 20K rows. So what happened was the legacy asp code was processing over 20K rows line by line and doing something with it. This caused huge CPU spike whenever that piece was asp code was running. Though i understood what was happening, I was a bit confused because, the asp code should have called with valid parameters. So i double checked the code and made sure. The next step i did was to make a change in the code to make sure that the stored procedure was called only if the params were valid (as in not null,i dont know why it would be null) .
As soon as i did that, CPU utilization went back to normal and i realized that the problem was temporarily fixed. I say temporarily because i still dont know why the stored procedure was called with null parameters. I ran several tests to figure out if ever, anywhere jumping across pages, the param became null, but i could not find it.
I then decided to look at the IIS default logs to look at all the incoming requests. (there is probably a lesson in there..i could have looked at the logs in the first place, but then i would not have learned the other techniques). I saw a bunch of requests at regular intervals from Google Bot and Bing Bot that directly targeted the pages with some invalid query strings and i realized that there was something wrong with the code, when those query strings was invalid or in wrong format. I modified the code to not even execute the rest of the code when a request with invalid querystring was made.
My next step was see how to prevent google bot from hitting the server and thats when the IIS request filtering came into play. You can block user-agents using this technique. The following code (added to your projects web.config ) blocks googlebot and bingbot if the request is for any asp file.
<security>
<requestFiltering>
<filteringRules>
<filteringRule name="GoogleBot" scanUrl="false" scanQueryString="false">
<scanHeaders>
<clear />
<add requestHeader="User-Agent" />
</scanHeaders>
<appliesTo>
<clear />
<add fileExtension=".asp" />
</appliesTo>
<denyStrings>
<clear />
<add string="Googlebot" />
<add string="bingbot" />
</denyStrings>
</filteringRule>
</filteringRules>
</requestFiltering>
</security>
pravsdatums 