These things tend to happen during those lovely quiet afternoons. I was enjoying reading about Mars colonization and genetically engineered bacteria terraforming when I got the call from our CEO. You probably already know the story, our VIC (Very Important Client, sometimes confused with GOD) has a problem. Even worst, the problem is identified in their production environment. I am to put on my superhero uniform and to go to client’s installation and face the “eye of the storm”. My mission is two-fold. My appearance is supposed to pacify the client and I might even do something about the problem, I have some whole 2 or 3 hours to come up with the solution.
Fortunately, once I meet with our guy working in-situ and our liaison (a junior manager has been assigned on client side to help us deal with the problem) the hysteria has subsided, and a few interesting details come into the light. The problem is by no means new, it has been reported more than a year ago, but for some reason nothing was done about it. It is a performance problem, so that is why it might not have been considered critical in the begging. What actually happened recently is that their CEO was annoyed by the problem and that made it hit the fan.
So, we start reviewing the app. My team-mate tells me that problem is produced only during login flow. We investigate bit further and by looking performance of components in Component Manager we are able to identify single offending component. In development environment, this component is taking some 40 seconds to respond, each time with exactly the same delay.
I ask them to monitor the component in production environment and to let me know. I will not receive the result until tomorrow, so I go back to the office. I am just too curious to wait, and I decide to take a look at component’s code. It is a COM+ component programmed in VB6 quite a few years ago. Component serves as a sort of Http proxy for stored procedures on MS SQL 2000, something of an in-house SOAP implementation that exposes stored procedures over http. Stored procedure name and parameters are received through Http request and reply rendered in form of Xml and sent back as a response.
A few lines almost immediately catch my eye:
strExecID = Request.Form("exec")
strParams = Request.Form("params")
‘ ...
Set Conn1 = CreateObject("ADODB.Connection")
Conn1.CursorLocation = adUseClient
Conn1.open strConnString
Set Rs1 = Conn1.Execute("EXEC " & strExec & " " & strParams)
‘ ... process Rs1 and generate Xml
Following problems are immediately evident:
1. Cursor Location
By setting cursor location to adUseClient, application will first pull down all the data over the wire before processing any of it. This should be changed to adUseServer.
2. Parameters
Parameters are passed as comma delimited string that is concatenated to “EXEC ” command + Stored Procedure name string that is used to execute query using the Connection object. This syntax is inferior to using ADODB Command and Parameters object. The problem in this case is that it would be probably too complicated to ask client component to supply all parameter metadata like type, size etc necessary when adding parameters to command. They decided to use position based parameter string executed on connection object instead. There are different solutions for this problem:
* Component could use some configuration data for this purpose
* ADODB Command is capable of obtaining parameter information from database. While this is not very efficient if it is done before each execution, some cache mechanism could be implemented in order to cut number of round-trips.
3. EXEC syntax
When executing stored procedures, standard ODBC syntax with CALL statement is the preferred way. This should reduce the number of compilations on the server. In order to check this, I decide to perform a small experiment.
The experiment
I place two controls on the form in VB and write the following code:
Private Sub UseCall_Click()
Dim Count As Integer
Dim Cn As ADODB.Connection
Set Cn = CreateObject(”ADODB.Connection”)
Cn.Open (”Provider=SQLOLEDB.1;Integrated Security=SSPI;Persist Security Info=False;” & _
"Initial Catalog=Northwind;Data Source=TESLATEAM")
Dim Rs As ADODB.Recordset
Do Until Count > 100
Set Rs = Cn.Execute(”{Call [Ten Most Expensive Products]}”)
Do Until Rs.EOF
Debug.Print Rs.Fields(1)
Rs.MoveNext
Loop
Count = Count + 1
Loop
End Sub
Private Sub UseExec_Click()
Dim Count As Integer
Dim Cn As ADODB.Connection
Set Cn = CreateObject(”ADODB.Connection”)
Cn.Open (”Provider=SQLOLEDB.1;Integrated Security=SSPI;Persist Security Info=False;” & _
"Initial Catalog=Northwind;Data Source=TESLATEAM")
Dim Rs As ADODB.Recordset
Do Until Count > 10
Set Rs = Cn.Execute(”EXEC [Ten Most Expensive Products]”)
Do Until Rs.EOF
Debug.Print Rs.Fields(1)
Rs.MoveNext
Loop
Count = Count + 1
Loop
End Sub
As you can see, the only difference between two event handlers is that in first case, {CALL } and in second EXEC syntax is used.
I open Performance Monitor and add SQL Compilations/sec counter. It is found under SQL Server:SQL Statistics performance object.
First, I press UseCall button. The counter is showing barely single SQL Compilation.
Using “CALL” syntax to execute Stored Procedure
However, when I use Exec syntax, there are repeatedly more than 10 Sql compilations per second. In production environment, this might incur significant load on the server.
Using “EXEC” syntax to execute Stored Procedure
This is enough to convince me that I am at the right track, and I proceed fixing the 3 problems I outlined above. Soon I have new version and I am ready to take the component to testing site we maintain at client’s premises.
Sobering up
I receive the monitoring results from production environment waiting in my inbox the next day. Things can really move fast when you have the right lever. The results are similar to one in testing environment, the component is taking a very long time to respond, with times raging from 700ms to over 50s. No doubt we have found our performance bottleneck.
I am off to the client with fixed code. I want to debug the component and to observe how the new code is being executed. I start executing the login test case and soon the IDE stops in debug mode reporting an error. The default Error Trapping options are not changed and IDE will break on errors in class module.
Damn, I have made the error somewhere and this might not be such an easy ride as I expected. I was already preparing for hero’s welcome back in the office. I guess that medal ceremony will have to wait for now.
Code is relatively simple and I should be able to find the bug without too much effort. I run the test case a few times but no error is produced until the command is executed. Finally, I have identified the error and it is not inside the component. The component is receiving non-existing stored procedure name for execution!
I decide to see how original version will do. The result is the same, the IDE breaks on the same error produced by non-existing stored procedure. This leaves me quite puzzled. Finally, I decide to change Error Trapping option to “Break on Unhandled Errors”. Voila! Application executes just fine, showing normal behavior, including the 40 second delay.
Following some dark alleys of error handling code, I finally fins out that client component handles the error produced in the component I just “fixed” and returns empty reply back the execution stack. As it happens, the component is not used at all and calling it is complete waist of time. And not just any waist of time, but very critical delay producing serious performance problem.
I soon implement the final solution eliminating the call to the component altogether. Application continues to work as it was supposed to be so I let the bygones by bygones. I explain the problem and the solution to the junior manager that is working with us and he is nice or content enough not to ask “But how this happened…”.
Finally, I am convinced once more that there is quite a lot of truth in Hoare’s proverbial sentence “Premature optimization is root of all evil”, cited by Diego in foreword to my book on refactoring in VB.
