SQL Server is Ignoring Me

[Jonathan Wood]

I have some SQL statements that are timing out with the message "Timeout
expired. The timeout period elapsed prior to completion of the operation or
the server is not responding." If I type the equivalent command directly
into a query window it works just fine. But sometimes SQL server just
doesn't respond and I don't understand why.

My code looks something like this:

private void toolStripButton1_Click(object sender, EventArgs e)
{
try
{
string qry = String.Format("SELECT TOP {0} * FROM URLs WHERE Status=0
AND PollCount < 5 ORDER BY URL", total);
using (SqlDataReader rdr = DataHelper.ExecDataReader(qry))
{
while (rdr.Read())
{
try
{

// ...

if (<error condition>)
throw new Exception("Custom Error");

// ...

DataHelper.ExecNonQuery("UPDATE URLs SET Status=1,
Comment=@Comment WHERE ID=@ID",
"@Comment", "Success",
"@ID", (int)rdr["ID"]);
}
catch (Exception ex)
{
DataHelper.ExecNonQuery("UPDATE URLs SET
Status=2,Comment=@Comment,PollCount=PollCount+1 WHERE ID=@ID",
"@Comment", ex.Message,
"@ID", (int)rdr["ID"]);
}
}
}
}
catch (Exception ex)
{
MessageBox.Show(String.Format("Unexpected error : {0}", ex.Message));
}
finally
{
// Clean up
}
}

For the most part, this code works just fine. But sometimes, when the
"Custom Error" condition is thrown, my ExecNonQuery() method in the catch
block times out. This causes the outter catch block (unexpected error) to be
thrown with the error mentioned at the top of this message.

I ran the SQL Server Profiler. Sure enough, it seems to indicate that the
UPDATE statement takes 30 seconds. But why?

Here's the data from SQL Server Profiler. I'm afraid I don't know how to
format it so it's easy to read. I've marked the problem query.

Audit Login -- network protocol: LPC
set quoted_identifier on
set arithabort off
set numeric_roundabort off
set ansi_warnings on
set ansi_padding on
set ansi_nulls on
set concat_null_yields_null on
set cursor_close_on_commit off
set implicit_transactions off
set language us_english
set dateformat mdy
set datefirst 7
set transaction isolation level read committed
.Net SqlClient Data Provider Jonathan Jonathan-PC\Jonathan 5964 54
2009-01-08 20:10:41.520
SQL:BatchStarting SELECT TOP 25000 * FROM URLs WHERE Status=0 AND PollCount
< 5 ORDER BY URL .Net SqlClient Data Provider Jonathan Jonathan-PC\Jonathan
5964 54 2009-01-08 20:10:41.520
Audit Login -- network protocol: LPC
set quoted_identifier on
set arithabort off
set numeric_roundabort off
set ansi_warnings on
set ansi_padding on
set ansi_nulls on
set concat_null_yields_null on
set cursor_close_on_commit off
set implicit_transactions off
set language us_english
set dateformat mdy
set datefirst 7
set transaction isolation level read committed
.Net SqlClient Data Provider Jonathan Jonathan-PC\Jonathan 5964 55
2009-01-08 20:10:41.990

----- HERE ----->>>

RPC:Completed exec sp_executesql N'SELECT COUNT(1) FROM Banned WHERE
Domain=@Domain',N'@Domain nvarchar(19)',@Domain=N'vps-web-hosting.net' .Net
SqlClient Data Provider Jonathan Jonathan-PC\Jonathan 0 7 0 0 5964 55
2009-01-08 20:10:41.990 2009-01-08 20:10:41.990
0X00000000040000001A00730070005F006500780065006300750074006500730071006C008600000082001800E7206E007600610072006300680061007200280034003800290060000000530045004C00450043005400200043004F0055004E0054002800310029002000460052004F004D002000420061006E006E0065006400200057004800450052004500200044006F006D00610069006E003D00400044006F006D00610069006E004E00000082001800E7206E00
Audit Logout .Net SqlClient Data Provider Jonathan Jonathan-PC\Jonathan 0 7
0 0 5964 55 2009-01-08 20:10:41.990 2009-01-08 20:10:41.990
RPC:Completed exec sp_reset_connection .Net SqlClient Data Provider
Jonathan Jonathan-PC\Jonathan 0 0 0 0 5964 55 2009-01-08 20:10:41.990
2009-01-08 20:10:41.990
0X00000000000000002600730070005F00720065007300650074005F0063006F006E006E0065006300740069006F006E00
Audit Login -- network protocol: LPC
set quoted_identifier on
set arithabort off
set numeric_roundabort off
set ansi_warnings on
set ansi_padding on
set ansi_nulls on
set concat_null_yields_null on
set cursor_close_on_commit off
set implicit_transactions off
set language us_english
set dateformat mdy
set datefirst 7
set transaction isolation level read committed
.Net SqlClient Data Provider Jonathan Jonathan-PC\Jonathan 5964 55
2009-01-08 20:10:41.990
RPC:Completed exec sp_executesql N'UPDATE URLs SET
Status=2,Comment=@Comment,PollCount=PollCount+1 WHERE ID=@ID',N'@Comment
nvarchar(17),@ID int',@Comment=N'Black-listed site',@ID=78147 .Net SqlClient
Data Provider Jonathan Jonathan-PC\Jonathan 0 3 0 30005 5964 55 2009-01-08
20:10:41.990 2009-01-08 20:11:12.003
0X00000000040000001A00730070005F006500780065006300750074006500730071006C00BE00000082001800E7206E0076006100720063006800610072002800370036002900980000005500500044004100540045002000550052004C007300200053004500540020005300740061007400750073003D0032002C0043006F006D006D0065006E0074003D00400043006F006D006D0065006E0074002C0050006F006C006C0043006F0075006E0074003D0050006F00
SQL:BatchCompleted SELECT TOP 25000 * FROM URLs WHERE Status=0 AND PollCount
< 5 ORDER BY URL .Net SqlClient Data Provider Jonathan Jonathan-PC\Jonathan
78 4953 0 30712 5964 54 2009-01-08 20:10:41.520 2009-01-08 20:11:12.240
Audit Logout .Net SqlClient Data Provider Jonathan Jonathan-PC\Jonathan 78
4953 0 379953 5964 54 2009-01-08 20:10:41.520 2009-01-08 20:17:01.473
Audit Logout .Net SqlClient Data Provider Jonathan Jonathan-PC\Jonathan 0
10 0 379483 5964 55 2009-01-08 20:10:41.990 2009-01-08 20:17:01.473

Jonathan

 

[Gregory A. Beamer]

I just cringed when I saw you were using a catch to retry something that
errors out. You are better to throw the work off to another routine with a
catch and have it return a failure and loop until you get success or reach n
tries, or similar.

As for the issue, I am not sure how your database is optimized. One way to
figure out if you have it optimized correctly is running profiler for a bit
while the website is running and hit the page in question numerous times.
Then take the workload file created and run the index wizard to get
suggestions. If none, you are optimized. If some, take a look and you might
find some neat ideas that can speed up queries.

I would also watch the database while the app was running and see if
anything is deadlocking. If you have a deadlock condition, you need to solve
it, as it can create timeouts.

These are the first ideas that come to mind.

--
Gregory A. Beamer
MVP: MCP: +I, SE, SD, DBA

Blog:
http://feeds.feedburner.com/GregoryBeamer

********************************************
| Think Outside the Box! |
********************************************

I have some SQL statements that are timing out with the message "Timeout
expired. The timeout period elapsed prior to completion of the operation
or the server is not responding." If I type the equivalent command directly
into a query window it works just fine. But sometimes SQL server just
doesn't respond and I don't understand why.

My code looks something like this:

private void toolStripButton1_Click(object sender, EventArgs e)
{
try
{
string qry = String.Format("SELECT TOP {0} * FROM URLs WHERE Status=0
AND PollCount < 5 ORDER BY URL", total);
using (SqlDataReader rdr = DataHelper.ExecDataReader(qry))
{
while (rdr.Read())
{
try
{

// ...

if (<error condition>)
throw new Exception("Custom Error");

// ...

DataHelper.ExecNonQuery("UPDATE URLs SET Status=1,
Comment=@Comment WHERE ID=@ID",
"@Comment", "Success",
"@ID", (int)rdr["ID"]);
}
catch (Exception ex)
{
DataHelper.ExecNonQuery("UPDATE URLs SET
Status=2,Comment=@Comment,PollCount=PollCount+1 WHERE ID=@ID",
"@Comment", ex.Message,
"@ID", (int)rdr["ID"]);
}
}
}
}
catch (Exception ex)
{
MessageBox.Show(String.Format("Unexpected error : {0}", ex.Message));
}
finally
{
// Clean up
}
}

For the most part, this code works just fine. But sometimes, when the
"Custom Error" condition is thrown, my ExecNonQuery() method in the catch
block times out. This causes the outter catch block (unexpected error) to
be
thrown with the error mentioned at the top of this message.

I ran the SQL Server Profiler. Sure enough, it seems to indicate that the
UPDATE statement takes 30 seconds. But why?

Here's the data from SQL Server Profiler. I'm afraid I don't know how to
format it so it's easy to read. I've marked the problem query.

Audit Login -- network protocol: LPC
set quoted_identifier on
set arithabort off
set numeric_roundabort off
set ansi_warnings on
set ansi_padding on
set ansi_nulls on
set concat_null_yields_null on
set cursor_close_on_commit off
set implicit_transactions off
set language us_english
set dateformat mdy
set datefirst 7
set transaction isolation level read committed
.Net SqlClient Data Provider Jonathan Jonathan-PC\Jonathan 5964 54
2009-01-08 20:10:41.520
SQL:BatchStarting SELECT TOP 25000 * FROM URLs WHERE Status=0 AND
PollCount
< 5 ORDER BY URL .Net SqlClient Data Provider Jonathan
Jonathan-PC\Jonathan
5964 54 2009-01-08 20:10:41.520
Audit Login -- network protocol: LPC
set quoted_identifier on
set arithabort off
set numeric_roundabort off
set ansi_warnings on
set ansi_padding on
set ansi_nulls on
set concat_null_yields_null on
set cursor_close_on_commit off
set implicit_transactions off
set language us_english
set dateformat mdy
set datefirst 7
set transaction isolation level read committed
.Net SqlClient Data Provider Jonathan Jonathan-PC\Jonathan 5964 55
2009-01-08 20:10:41.990

----- HERE ----->>>

RPC:Completed exec sp_executesql N'SELECT COUNT(1) FROM Banned WHERE
Domain=@Domain',N'@Domain nvarchar(19)',@Domain=N'vps-web-hosting.net'
.Net
SqlClient Data Provider Jonathan Jonathan-PC\Jonathan 0 7 0 0 5964 55
2009-01-08 20:10:41.990 2009-01-08 20:10:41.990
0X00000000040000001A00730070005F006500780065006300750074006500730071006C008600000082001800E7206E007600610072006300680061007200280034003800290060000000530045004C00450043005400200043004F0055004E0054002800310029002000460052004F004D002000420061006E006E0065006400200057004800450052004500200044006F006D00610069006E003D00400044006F006D00610069006E004E00000082001800E7206E00
Audit Logout .Net SqlClient Data Provider Jonathan Jonathan-PC\Jonathan 0
7
0 0 5964 55 2009-01-08 20:10:41.990 2009-01-08 20:10:41.990
RPC:Completed exec sp_reset_connection .Net SqlClient Data Provider
Jonathan Jonathan-PC\Jonathan 0 0 0 0 5964 55 2009-01-08 20:10:41.990
2009-01-08 20:10:41.990
0X00000000000000002600730070005F00720065007300650074005F0063006F006E006E0065006300740069006F006E00
Audit Login -- network protocol: LPC
set quoted_identifier on
set arithabort off
set numeric_roundabort off
set ansi_warnings on
set ansi_padding on
set ansi_nulls on
set concat_null_yields_null on
set cursor_close_on_commit off
set implicit_transactions off
set language us_english
set dateformat mdy
set datefirst 7
set transaction isolation level read committed
.Net SqlClient Data Provider Jonathan Jonathan-PC\Jonathan 5964 55
2009-01-08 20:10:41.990
RPC:Completed exec sp_executesql N'UPDATE URLs SET
Status=2,Comment=@Comment,PollCount=PollCount+1 WHERE ID=@ID',N'@Comment
nvarchar(17),@ID int',@Comment=N'Black-listed site',@ID=78147 .Net
SqlClient
Data Provider Jonathan Jonathan-PC\Jonathan 0 3 0 30005 5964 55 2009-01-08
20:10:41.990 2009-01-08 20:11:12.003
0X00000000040000001A00730070005F006500780065006300750074006500730071006C00BE00000082001800E7206E0076006100720063006800610072002800370036002900980000005500500044004100540045002000550052004C007300200053004500540020005300740061007400750073003D0032002C0043006F006D006D0065006E0074003D00400043006F006D006D0065006E0074002C0050006F006C006C0043006F0075006E0074003D0050006F00
SQL:BatchCompleted SELECT TOP 25000 * FROM URLs WHERE Status=0 AND
PollCount
< 5 ORDER BY URL .Net SqlClient Data Provider Jonathan
Jonathan-PC\Jonathan
78 4953 0 30712 5964 54 2009-01-08 20:10:41.520 2009-01-08 20:11:12.240
Audit Logout .Net SqlClient Data Provider Jonathan Jonathan-PC\Jonathan
78
4953 0 379953 5964 54 2009-01-08 20:10:41.520 2009-01-08 20:17:01.473
Audit Logout .Net SqlClient Data Provider Jonathan Jonathan-PC\Jonathan 0
10 0 379483 5964 55 2009-01-08 20:10:41.990 2009-01-08 20:17:01.473

Jonathan

 

[Jonathan Wood]

I just cringed when I saw you were using a catch to retry something that
errors out. You are better to throw the work off to another routine with a
catch and have it return a failure and loop until you get success or reach
n tries, or similar.

I'm not sure I understand. The catch block doesn't retry anything. Instead,
it flags the record as having failed. Can you clarify?

As for the issue, I am not sure how your database is optimized. One way to
figure out if you have it optimized correctly is running profiler for a
bit while the website is running and hit the page in question numerous
times. Then take the workload file created and run the index wizard to get
suggestions. If none, you are optimized. If some, take a look and you
might find some neat ideas that can speed up queries.

Actually, this code is running in a desktop application. (Although it
manipulates a database that will be online.) I don't know anything about a
"workload file". Perhaps I can find out about that.

I would also watch the database while the app was running and see if
anything is deadlocking. If you have a deadlock condition, you need to
solve it, as it can create timeouts.

The only thing I can imagine is that I do have a deadlock. I would've
guessed the profiler might tell me about that but I guess not. That's where
I'm stuck.

Thanks.

Jonathan

 

[Trevor Benedict]

If you are using an ADO and a Stored Procedure, it has a Timeout setting
that you can specifiy. Are you using the default (90 seconds or so)?

Regards,

Trevor Benedict

 

[Jonathan Wood]

No stored procedure. 30 seconds. I determined the database is blocking. See
the "Database Blocking -- Why?" thread for the latest info.

Thanks.

Jonathan