views:

126

answers:

1

I have some code that allows users to upload file attachments into a varbinary(max) column in SQL Server from their web browser. It has been working perfectly fine for almost two years, but all of a sudden it stopped working. And it stopped working on only the production database server -- it still works fine on the development server.

I can only conclude that the code is fine and there is something up with the instance of SQL Server itself. But I have no idea how to isolate the problem.

I insert a record into the ATTACHMENT table, only inserting non-binary data like the title and the content type, and then chunk-upload the uploaded file using the following code:

// get the file stream

 System.IO.Stream fileStream = postedFile.InputStream;

// make an upload buffer

byte[] fileBuffer;
fileBuffer = new byte[1024];

// make an update command

SqlCommand fileUpdateCommand = new SqlCommand("update ATTACHMENT set ATTACHMENT_DATA.WRITE(@Data, NULL, NULL) where ATTACHMENT_ID = @ATTACHMENT_ID", sqlConnection, sqlTransaction);

fileUpdateCommand.Parameters.Add("@Data", SqlDbType.Binary);
fileUpdateCommand.Parameters.AddWithValue("@ATTACHMENT_ID", newId);

while (fileStream.Read(fileBuffer, 0, fileBuffer.Length) > 0)
{

     fileUpdateCommand.Parameters["@Data"].Value = fileBuffer;
     fileUpdateCommand.ExecuteNonQuery(); <------ FAILS HERE

}

fileUpdateCommand.Dispose();
fileStream.Close();

Where it says "FAILS HERE", it sits for a while and then I get a SQL Server timeout error on the very first iteration through the loop. If I connect to the development database instead, everything works fine (it runs through the loop many, many times and the commit is successful).

Both servers are identical (SQL Server 9.0.3042) and the schemas are identical as well.

When I open Activity Monitor right after the timeout to see what's going it, it says the last command is

(@Data binary(1024),@ATTACHMENT_ID decimal(4,0))update ATTACHMENT set ATTACHMENT_DATA.WRITE(@Data, NULL, NULL) where ATTACHMENT_ID = @ATTACHMENT_ID

which I would expect but it also says it has a status of "Suspended" and a wait type of "PAGEIOLATCH_SH". I looked this up and it seems to be a bad thing but I can't find anything specific to my stuation.

Ideas?

OK, here's the output from sys.dm_exec_requests:

session_id request_id  start_time              status                         command          sql_handle                                                                                                                         statement_start_offset statement_end_offset plan_handle                                                                                                                        database_id user_id     connection_id                        blocking_session_id wait_type                                                    wait_time   last_wait_type                                               wait_resource                                                                                                                                                                                                                                                    open_transaction_count open_resultset_count transaction_id       context_info                                                                                                                                                                                                                                                       percent_complete estimated_completion_time cpu_time    total_elapsed_time scheduler_id task_address       reads                writes               logical_reads        text_size   language                                                                                                                         date_format date_first quoted_identifier arithabort ansi_null_dflt_on ansi_defaults ansi_warnings ansi_padding ansi_nulls concat_null_yields_null transaction_isolation_level lock_timeout deadlock_priority row_count            prev_error  nest_level  granted_query_memory executing_managed_code
---------- ----------- ----------------------- ------------------------------ ---------------- ---------------------------------------------------------------------------------------------------------------------------------- ---------------------- -------------------- ---------------------------------------------------------------------------------------------------------------------------------- ----------- ----------- ------------------------------------ ------------------- ------------------------------------------------------------ ----------- ------------------------------------------------------------ ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- ---------------------- -------------------- -------------------- ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ ---------------- ------------------------- ----------- ------------------ ------------ ------------------ -------------------- -------------------- -------------------- ----------- -------------------------------------------------------------------------------------------------------------------------------- ----------- ---------- ----------------- ---------- ----------------- ------------- ------------- ------------ ---------- ----------------------- --------------------------- ------------ ----------------- -------------------- ----------- ----------- -------------------- ----------------------
59         0           2010-06-16 10:49:26.130 suspended                      UPDATE           0x020000003499A22E28282311CAF8CE0730402C45DCD89961                                                                                 0                      0                    0x06000E003499A22EB881FD73000000000000000000000000                                                                                 14          5           4AB28A88-B4B9-4B54-B4F4-311D42C5EA29 0                   PAGEIOLATCH_SH                                               0           PAGEIOLATCH_SH                                               14:1:547920                                                                                                                                                                                                                                                      1                      1                    226115095            0x                                                                                                                                                                                                                                                                 0                0                         187         3687               0            0x0088B3D8         921                  0                    240166               2147483647  us_english                                                                                                                       mdy         7          1                 1          1                 0             1             1            1          1                       2                           -1           0                 1                    0           3           490                  0

(1 row(s) affected)

EDIT:

OK, I rebooted, no dice (needed to install some patches anyway). Deleted and rebuilt the PK on ATTACHMENT_ID, no dice. Then I rebuilt the statistics for the table and now it seems happy. I can only guess there was something off in the statistics that was causing the query optimizer to freak out.

+1  A: 

From the symptoms it looks like the query times out due to having to perform a table scan. Does the table ATTACHMENT has an index on ATTACHMENT_ID on both servers? Can you double check? If the schemas are identical but both are missing the index, do the tables have comparable size? Could be that the scan on test machine lasts less than 30 seconds, while the one on production lasts enough to time out. In which case you need and index on ATTACHMENT_ID.

Remus Rusanu
ATTACHMENT_ID is PK and Identity, and the index is there (PK__ATTACHMENT__7E6CC920, ATTACHMENT_ID (ASC), Type=Primary Key). The ATTACHMENT table in development is smaller, though.When I retrieve (download) the attachments through the web interface, the query uses ATTACHMENT_ID in the where clause and that runs with no performance issues at all.
pjabbott
BTw, you should use a buffer size of 8040 for .WRITE max efficiency: "For best performance, we recommend that data be inserted or updated in chunk sizes that are multiples of 8040 bytes." http://msdn.microsoft.com/en-us/library/ms177523.aspx
Remus Rusanu
I'm having a hard time believing that the query blocks on `PAGEIOLATCH_SH` if the index is present. Get the @@SPID on the connection before you try to update, and while is waiting for time out, check the sys.dm_exec_requests for that session_id. I expect it to be blocked waiting for row lock, ie. the update is blocked by readers. Blocking for PAGEIOLATCH_SH just doesn't add up.
Remus Rusanu
I added the output to sys.dm_exec_requests to the original post. BTW, table in prod is 13GB and ~7000 rows, development is 9GB and ~5000 rows.
pjabbott
Yes, it is PAGEIOLATCH_SH. Notice though that it has a very hight logical_reads count: 240166, that means it had to go through 240166 pages (so far) for this request. That is nearly 2Gb. Can you post the execution plan, `SELECT * FROM sys.dm_exec_query_plan(0x06000E003499A22EB881FD73000000000000000000000000)`
Remus Rusanu
dm_exec_query_plan resulted in: dbid: NULL, objectid: NULL, encrypted: 1, query_plan: NULL; huh?
pjabbott
Your statement is encrypted: `encrypted: 1`
Remus Rusanu
@Remus but it's adhoc SQL and shows up in Activity Monitor. Is this expected? If not might this indicate an encrypted trigger?
Martin Smith
@Martin: I haven't though at that at all... Not a big trigger fan myself, u see... It very well might be the problem, indeed. @pjabbott: any trigger added on the table in production?
Remus Rusanu
Nope, no triggers. I'm going to reboot tonight (it hasn't been done since 2009) and see what happens. But for now, there's other things I need to get to. Thanks, everyone.
pjabbott