Charlie Wears Lead Boots
I finished my previous weblog entry by saying that I would teach myself enough SQL so that I could move a little bit of logic to the database, rather than keeping the logic in the C# code and hitting the database multiple times.
Fortunately, a friend has offered to help me with writing the queries, and I’ll report on how that goes. So that we focus on the most “chatty” parts of Charlie’s database access, I decided that I should use SQL Profiler to see what is going on at the database. I “touched” the Global.asax file in order to mark the Charlie application for recycling, and requested the home page. I switched to SQL Profiler and looked at its trace. I was horrified.
To start with, the trace showed signficantly more hits to the database than should have occurred. Since this is an honest account of Charlie’s development, I’ll give you the true figure, as much as I’d like to halve it in order to save some face. The first page request required 49 hits to the database. Just as troubling, there was a two-second delay between two subsequent database hits. What the heck was Charlie doing in that time?
I switched on Charlie’s logging plugin, cleared the SQL Profiler trace, and again forced the Charlie application to recycle. After requesting the home page again, I now had a record of what Charlie was doing, and what the database was doing. I brought the details together in an Excel spreadsheet, and analysed what was going on.
The first problem was that Charlie was issuing the same queries over and over. In fact, I counted 23 redundant queries. This is a coding error on my part, and some good old-fashioned debugging will solve it. So, while I am suitably embarrassed, I am not too worried about this.
The second problem was that Charlie was issuing three queries that should really be combined into one query. This is the logic problem that I prompted this investigation. Hopefully, my friend can help me here.
The third problem was the Charlie was querying once for each entity, and then once again for each entity’s roles. Performing two queries for each entity seems unnecessary, so I may look at combining the queries.
The fourth problem was the database connection was opened and closed eight times. It is my understanding that there is some overhead involved in opening a new connection, so I may consider keeping a connection open when I know another query is imminent.
If I address each of the above four problems, I should be able to get the initial database access down to about six queries and two connections. That will solve the “chatty” database access problem. But, there was a bigger problem.
The fifth problem was that the SQL Profiler trace showed a two-second gap between two adjacent queries. The output of the logging plugin shows where the delay occurs, even though I don’t know the cause of the delay.
Charlie’s extension of the HttpApplication class (the class behind the Global.asax file) logs the time immediately before the target HttpHandler receives its ProcessRequest command. Then, that HttpHandler logs the time when it starts processing the request. The log shows that there is a 2.1 second delay. Charlie is not doing anything at all during this time. ASP.NET is doing something. What the hell is it doing that is taking 2.1 seconds?
First, it is not a logging error, because the same delay is recorded by both Charlie and SQL Profiler. The delay is real.
Second, it is not a delay caused by ASP.NET parsing an .aspx file and storing the dynamically-generated DLL. The HttpHandler used by Charlie is a ready-to-go class that is fully contained within an assembly.
Third, this delay only occurs during the first page request after recycling the ASP.NET application. However, it is not the time taken to restart the application, since both the logging plugin and SQL Profiler do not come into play until after the application has started and the request has commenced processing.
What is ASP.NET doing that takes 2.1 seconds? The HttpHandler is loaded and ready to go, but there is a marked delay before anything happens.
To put this delay in context, the request for the Home page after an application restart takes 3.1 seconds. A subsequent request for the About page (so there are a few database hits for the new content) takes 0.1 second. A new request for the Home page (so everything is drawn from cache) takes 0.03 seconds. This inexplicable 2.1 second delay during the processing of the first request is far and away the slowest part of Charlie.
As I write this, I have no idea why there is a long delay before the first HttpHandler executes. I fully understand the delay caused by the ASP.NET application restarting and reloading. But I do not understand what ASP.NET is doing from the time it fires the PreRequestHandlerExecute event to the time the handler actually executes. If I learn the cause of the delay, I will of course let you know. And if you know the cause, you will of course let me know, won’t you?
By the way, I know that optimisation should be a final polishing step. But, this investigation did not come about due to a desire to optimise Charlie, but came about as a consequence of using SQL Profiler to address Charlie’s chatty database access code.
by Alister Jones | Next up: The Valley of Data Access - Part 5 →
----
Post a Comment