Recently one of the developers was profiling an application to see where improvements could be made to the code. He was using JetBrains profiler,
http://www.jetbrains.com/profiler/
and this was indicating that retrieving a string using from a SqlDataReader using reader.GetString() was taking a long time.
To recreate the problem, I firstly populated a similar database – the script in the previous entry is sufficient.
http://www.noelwatson.com/blog/PermaLink,guid,b8d1d44e-0058-43d7-8635-25513e9bc86e.aspx
although you will have to add an extra zero to the loop – 1 million records wasn’t enough to recreate the problem.
DECLARE @DateSubtract DECIMAL(9,4)
DECLARE @Counter INT
SELECT @Counter = 0
WHILE @Counter < 10000000
BEGIN
SELECT @DateSubtract = RAND() * 100000
INSERT INTO LOG (LogDateTime, Details)
VALUES (DATEADD(mi, - @DateSubtract, GETDATE()), 'TEST')
SELECT @Counter = @Counter + 1
END
A simplified version of the stored procedure is shown below
ALTER PROCEDURE p_LogSearch_s
(
@ip_StartDate DATETIME,
@ip_EndDate DATETIME
)
AS
SELECT Details, LogDateTime FROM LOG
WHERE (@ip_StartDate IS NULL OR LogDateTime >= @ip_StartDate) AND (@ip_EndDate IS NULL OR LogDateTime < @ip_EndDate)
Test code is shown below. This is called 20 times
private void RetrieveData()
{
SqlConnection sqlConn = null;
SqlCommand sqlCmd = null;
SqlDataReader reader = null;
SqlParameter param = null;
string strSqlConn;
string logDetails;
DateTime logTime;
strSqlConn = @"Data Source=(local); Initial Catalog=Log;Integrated Security=SSPI";
sqlConn = new SqlConnection(strSqlConn);
sqlCmd = new SqlCommand();
sqlConn.Open();
sqlCmd.CommandText = "p_LogSearch_s";
sqlCmd.CommandType = CommandType.StoredProcedure;
sqlCmd.Connection = sqlConn;
param = new SqlParameter("@ip_StartDate",SqlDbType.SmallDateTime);
param.Value = new DateTime(2005,12,7,21,30,0,0);
sqlCmd.Parameters.Add(param);
param = new SqlParameter("@ip_EndDate",SqlDbType.SmallDateTime);
param.Value = new DateTime(2005,12,8);
sqlCmd.Parameters.Add(param);
reader = sqlCmd.ExecuteReader();
while (reader.Read())
{
logDetails = reader.GetString(0);
logTime = reader.GetDateTime(1);
}
}
We are retrieving 2.5 hours worth of data - 15161 rows
Looking at the results, it is interesting to see that GetString() takes almost 20 times as long as GetDate(). However, this is because GetString() is the first call to retrieve the next row of the data, so will take longer and is a red herring. If we were to swap GetDateTime() above GetString(), the orders would reverse. 303220 is the number of hits we are expecting (20 iterations * 15161 rows), the Read method reads the extra time when the end of the recordset is reached.
Note that some of the calls (e.g FPushMessageLoop) can be ignored as they are related to form population
Solutions
1. Modify Isolation level
One way to improve performance is to set the isolation level to read uncommitted – this is acceptable when reading log data as we are not too fussed if the occasional record is uncommitted. This improves performance by around 20%, although gives an even more misleading result in JetBrains!
2. Modify the stored procedure
The stored procedure can be rewritten
ALTER PROCEDURE p_LogSearch_s
(
@ip_StartDate DATETIME,
@ip_EndDate DATETIME
)
AS
SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED
SELECT Details, LogDateTime FROM LOG
WHERE (LogDateTime >= @ip_StartDate) AND (LogDateTime < @ip_EndDate)
and the results are dramatic
However, this stored procedure as it stands may be unacceptable as it may be the case that null variables must be passed to the stored procedure.
3. Improve performance reading from the datareader
With reference to the following link
http://www.sqljunkies.com/WebLog/amachanic/archive/2005/04/06/10462.aspx
it is possible to improve performance when accessing the datareader
while (reader.Read())
{
logDetails = reader.GetString(0);
logTime =reader.GetDateTime(1);
}
becomes
while (reader.Read())
{
logDetails = (string)reader[0];
logTime =(DateTime)reader[1];
}
This improves performance marginally, get_item taking 59064ms is less than the combined total of GetString (58803ms) and GetDateTime (389ms) in test 1 (UNCOMMITTED).
4. Use a dataset
I did this just out of interest, as I didn't believe performance would be improved
while (reader.Read())
{
logDetails = reader.GetString(0);
logTime =reader.GetDateTime(1);
}
becomes
DataSet ds = new DataSet();
SqlDataAdapter da;
da = new SqlDataAdapter(sqlCmd);
da.Fill(ds);
foreach(DataRow dr in ds.Tables[0].Rows)
{
logDetails = (string)dr[0];
logTime =(DateTime)dr[1];
}
65312 milliseconds compares favourably with test 1, (note that in the real world, I wouldn't iterate through the dataset but instead would bind directly to a grid) which has
GetString 58803
Read 3825
ExecuteReader 1398
GetDateTime 389
=64415ms
Dataset vs. DataReaders can be found here
http://msdn.microsoft.com/library/default.asp?url=/library/en-us/dnbda/html/bdadotnetarch031.asp
Conclusion
Modifying the stored procedure would be the obvious choice. Using code such as
(@ip_StartDate IS NULL OR LogDateTime >= @ip_StartDate)
Doesn’t allow the index to be used correctly (uses a scan rather than a seek)
An alternative is to use a parent stored procedure, and call individual child stored procedures dependant on the parameters passed to the parent sp. Maintaining these can be a headache, but are necessary if performance is critical.