Check Your SQL
As I mentioned in the introduction, I often use time to measure the performance of my T-SQL and stored procedures. Therefore, I’m interested in the following values:
- How long does the real execution take?
- And how much time is needed on the network?
This not only can help you improving your code in the development phase. But you can also trace a client application that lacks performance in your productive system.
Query Analyzer can only show you the durations while executing. But I’m also interested in the network, and how it affects performance!
Now, I’ll show you how to test how long it takes for your T-SQL code to run. You can modify the code to test your stored procedures as well. To get the starting and ending DATETIME from the server is easy, with this stored procedure:
Create Procedure spTestSQL
@strSQL as nvarchar(400),
@dtStart datetime OUTPUT,
@dtEnd datetime OUTPUT
As
Set nocount on
Set @dtStart= GetDate()
Exec sp_executeSQL @strSql
Set @dtEnd= GetDate()
return
In the ‘lost milliseconds’ section, I told you about the VB Timer() function. Because the integer part of a date variable contains the date-part, and Timer() counts the seconds of a day, you can simulate your own date variable with milliseconds by using the DOUBLE data type:
Dim dblNow as Double
DblNow = Int(Now) + timer / 86400 ‘ the date from Now + the time from Timer!
Debug.Print FormatDt(dblNow)
Finally, to measure the SQL, you will easily get through this code:
Sub TestSQL()
Dim cmd As New ADODB.Command
Dim dblCltStart As Double, dblCltEnd As Double ‘ client dates
Dim dblSvrStart As Double, dblSvrEnd As Double ‘ server dates
With cmd
.ActiveConnection = “Your connection string”
.CommandType = adCmdStoredProc
‘ !!!CAUTION!!!!! ‘ clear server’s caches;
‘only sysadmins can execute this command;
‘don’t use this command on productive systems!
.CommandText = “DBCC DROPCLEANBUFFERS” ‘ !!!CAUTION!!!!!
‘ init command with the SQL to test and the start/end datetime parameters
.CommandText = “spTestSQL”
.Parameters.Append .CreateParameter(“@strSQL”, adVarChar, adParamInput, 400, “YourSQL”)
.Parameters.Append .CreateParameter(“@dtStart”, adDate, adParamOutput)
.Parameters.Append .CreateParameter(“@dtEnd”, adDate, adParamOutput)
dblCltStart = Int(Now) + timer / 86400 ‘ client’s start with milliseconds
.Execute ‘run procedure spTestSQL
dblCltEnd = Int(Now) + timer / 86400 ‘ client’s end with milliseconds
dblSvrStart = .Parameters(“@dtStart”) ‘ server’s start
dblSvrEnd = .Parameters(“@dtEnd”) ‘ server’s end
End With
Set cmd = Nothing
‘output date/time and durations
Debug.Print _
“Code started at: ” & FormatDt(dblCltStart) & vbCrLf & _
“Server started at: ” & FormatDt(dblSvrStart) & vbCrLf & _
“Sever ended at: ” & FormatDt(dblSvrEnd) & vbCrLf & _
“Code ended at: ” & FormatDt(dblCltEnd) & vbCrLf & _
vbCrLf & _
“Full duration: ” & FormatDt(dblCltEnd – dblCltStart, “hh:mm:ss”) & vbCrLf & _
“Server duration: ” & FormatDt(dblSvrEnd – dblSvrStart, “hh:mm:ss”) & vbCrLf & _
“Network duration: ” & _
FormatDt((dblCltEnd – dblCltStart) – (dblSvrEnd – dblSvrStart), “hh:mm:ss”)
End Sub
Of course you must substitute ”Your connection String” and “YourSQL” in the code above. In order to omit caching effects, I have entered the DBCC DROPCLEANBUFFERS command, which clears all caches. You need sysadmin rights to execute this. I warn you not to use it on a production system!
After execution of the code, you will see the a similar output in your debug-window:
Code started at: 2004-07-23 18:13:13.989
Server started at: 2004-07-23 18:13:12.183
Sever ended at: 2004-07-23 18:13:20.200
Code ended at: 2004-07-23 18:13:22.771
Full duration: 00:00:08.782
Server duration: 00:00:08.017
Network duration: 00:00:00.765
You may have noticed the different timestamps on the server and client. That’s because the two clocks are not synchronized. For that reason the durations are correct, but you cannot calculate the time between sending and executing the command. If you like to do that, you can synchronize the two clocks by hardware or software. (E.g. use the sample code from http://www.thescarms.com/vbasic/syncclock.asp with your server’s ip.)
You will be astonished, if you run this code on a local SQL Server or MSDE installation.
Code started at: 2004-07-23 21:54:05.806
Server started at: 2004-07-23 21:54:05.803
Sever ended at: 2004-07-23 21:54:05.863
Code ended at: 2004-07-23 21:54:05.866
Full duration: 00:00:00.060
Server duration: 00:00:00.060
Network duration: 00:00:00.000
It seems like the SQL Server starts before it gets the command to run. Why? Because SQL Server 2000 is so smart it can guess there is soon a command coming in!