locked
BLOCKING question RRS feed

  • Question

  •  


    We are encountering a problem with our application that processes a "print queue"
    table.

    Our application is an asp.Net application, running within IIS 7 connecting to a SQL Server 2008 SP1 (STD)
    on a separate host. It uses the native .Net SQL Server client provider.

    Windows 2008 R2 Server everywhere (although the Windows OS does not appear to be significant).

    The problem is that we find a spid that is blocking other spid's on the database.

    The blocking spid is an update every time.


    example:

    UPDATE PRINT_QUEUE SET PRQ_STAGE = '20' WHERE PRQ_XDOC = 'PXC0000005' AND PRQ_STAGE = '10'

    If we copy the update statement into a SQL Server query window, it completes successfully and the showplan
    indicates no further indexes are beneficial.

    When the blocking occurs, we notice the blocking spid has left an open transaction on the database.

    We have easily reproduced the problem in our test environment (with a single client running in a debug session) and these are the results of our traces:


    ##############################
    (1) SQL SERVER PROFILER TRACE
    ##############################

    We see a SELECT * FROM PRINT_QUEUE..... query arrive, (BatchStarting) then immediately afterwards, an UPDATE PRINT_QUEUE... query arrives.

     

    SQL:BatchStarting SELECT * FROM PRINT_QUEUE WHERE PRQ_ORG = '0003' AND PRQ_STAGE = '10' ORDER BY PRQ_DATECREATED ASC,PRQ_XDOC ASC .Net SqlClient Data Provider  SVRLGN1     2632 54 2010-10-29 09:38:06.110                              
    SQLTransaction                .Net SqlClient Data Provider  SVRLGN1    0 2632 54 2010-10-29 09:38:06.110 2010-10-29 09:38:06.110  14 MYDBTEST  55736074 1 WS10468  0X5EC66F758D54D84DBC2DF80440B18018  2 SVR1 SVRLGN1   184220994 0 0 sort_init 0 - Begin         
    SQL:BatchStarting   UPDATE PRINT_QUEUE SET PRQ_STAGE = '20' WHERE PRQ_XDOC = 'PXC0000005' AND PRQ_STAGE = '10' .Net SqlClient Data Provider  SVRLGN1     2632 54 2010-10-29 09:38:10.343                              
    SQLTransaction                .Net SqlClient Data Provider  SVRLGN1    0 2632 54 2010-10-29 09:38:10.343 2010-10-29 09:38:10.343  14 MYDBTEST  55736076 1 WS10468  0X5EC66F758D54D84DBC2DF80440B18018  3 SVR1 SVRLGN1   184220995 0 0 UPDATE 0 - Begin         

     

    ###############################
    (2) OUTPUT FROM "DBCC OPENTRAN" 
    ###############################

     

    ActiveTransaction         Details
    ------------------------- ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
    OLDACT_SPID               54
    OLDACT_UID                -1
    OLDACT_NAME               UPDATE
    OLDACT_LSN                (169:2140:1)
    OLDACT_STARTTIME          Oct 29 2010  9:38:10:343AM
    OLDACT_SID                0x5ec66f758d54d84dbc2df80440b18018


    ##########################################################################
    (3) OUTPUT FROM "SELECT open_tran from master..sysprocesses where spid=54"
    ##########################################################################

    open_tran
    ---------
    0
    2

     

    #########################################
    (4) OUTPUT FROM "DBCC OPENTRAN(MYDBTEST)"
    #########################################

    Transaction information for database 'MYDBTEST'.

    Oldest active transaction:
        SPID (server process ID): 54
        UID (user ID) : -1
        Name          : UPDATE
        LSN           : (169:2140:1)
        Start time    : Oct 29 2010  9:38:10:343AM
        SID           : 0x5ec66f758d54d84dbc2df80440b18018
    DBCC execution completed. If DBCC printed error messages, contact your system administrator.

     

    ###############################################################################################################################################################
    (5) OUTPUT FROM " SELECT t1.resource_type,t1.resource_database_id,t1.resource_associated_entity_id,t1.request_mode,t1.request_session_id,t2.blocking_session_id
                      FROM sys.dm_tran_locks as t1 INNER JOIN sys.dm_os_waiting_tasks as t2 ON t1.lock_owner_address = t2.resource_address; "
    ###############################################################################################################################################################

     

    resource_type                                                resource_database_id resource_associated_entity_id request_mode                                                 request_session_id blocking_session_id
    ------------------------------------------------------------ -------------------- ----------------------------- ------------------------------------------------------------ ------------------ -------------------
    KEY                                                          14                   72057594051035136             X                                                            54                 54

     

    ##################################################
    (6) sysprocesses OUTPUT FOR THE BLOCKING SPID (54)
    ##################################################


    spid   kpid   blocked waittype waittime             lastwaittype                     waitresource                                                                                                                                                                                                                                                     dbid   uid    cpu         physical_io          memusage    login_time              last_batch              ecid   open_tran status                         sid                                                                                                                                                                            hostname                                                                                                                         program_name                                                                                                                     hostprocess cmd              nt_domain                                                                                                                        nt_username                                                                                                                      net_address  net_library  loginame                                                                                                                         context_info                                                                                                                                                                                                                                                       sql_handle                                 stmt_start  stmt_end    request_id
    ------ ------ ------- -------- -------------------- -------------------------------- ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- ------ ------ ----------- -------------------- ----------- ----------------------- ----------------------- ------ --------- ------------------------------ ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ -------------------------------------------------------------------------------------------------------------------------------- -------------------------------------------------------------------------------------------------------------------------------- ----------- ---------------- -------------------------------------------------------------------------------------------------------------------------------- -------------------------------------------------------------------------------------------------------------------------------- ------------ ------------ -------------------------------------------------------------------------------------------------------------------------------- ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ ------------------------------------------ ----------- ----------- -----------
    54     1504   0       0x0063   1193                 ASYNC_NETWORK_IO                                                                                                                                                                                                                                                                                  14     5      15          0                    4           2010-10-29 09:37:39.817 2010-10-29 09:37:39.863 0      0         suspended                      0x5EC66F758D54D84DBC2DF80440B1801800000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000 WS10468                                                                                                                          .Net SqlClient Data Provider                                                                                                     2632        SELECT                                                                                                                                                                                                                                                                             205A7F50427F TCP/IP       OSTEST                                                                                                                           0x0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000 0x01000E00D9DEF601C0CFFF250000000000000000 0           -1          2
    54     5268   54      0x0005   179016               LCK_M_X                          KEY: 14:72057594051035136 (a7010abd9e03)                                                                                                                                                                                                                         14     5      0           0                    5           2010-10-29 09:37:39.817 2010-07-06 12:58:04.907 0      2         suspended                      0x5EC66F758D54D84DBC2DF80440B1801800000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000 WS10468                                                                                                                          .Net SqlClient Data Provider                                                                                                     2632        UPDATE                                                                                                                                                                                                                                                                             205A7F50427F TCP/IP       OSTEST                                                                                                                           0x0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000 0x01000E00D80CF434E87B3E060000000000000000 104         -1          3

     

     

    Is this problem as being due simply to the application not waiting for the results from the SELECT to be sent to the client,
      when it issues the UPDATE statement? (the SQL Server Profiler trace shows only BatchStarting for the SELECT by the time the UPDATE is issued)

    (NOTE: the SELECT query has been improved by adding an additional nonclustered index on the PRINT_QUEUE table, but still the problem persists.)

    If my intepretation of this problem is correct, then what can be done within the application to handle this situation?

    Thank you for any assistance and advice you may be able to offer.


    AMackan

    Friday, October 29, 2010 10:18 AM

Answers

  • It sounds like the UPDATE statement doesn't complete OR that the queries are in a transaction which is never committed. Are you using IMPLICIT TRANSACTIONS? In your test environment, check @@TRANCOUNT after the update statement to see if there is an open tran and then commit it.

     


    every day is a school day
    Friday, October 29, 2010 11:14 AM

All replies

  • It sounds like the UPDATE statement doesn't complete OR that the queries are in a transaction which is never committed. Are you using IMPLICIT TRANSACTIONS? In your test environment, check @@TRANCOUNT after the update statement to see if there is an open tran and then commit it.

     


    every day is a school day
    Friday, October 29, 2010 11:14 AM
  • What is @@version?

    It would be helpful if you post sufficient scripts so that we can test.

    Are you using stored procedures? If not, convert your queries into stored procedures and let us know what happens.


    Kalman Toth, SQL Server & Business Intelligence Training; SQL 2008 GRAND SLAM
    Friday, October 29, 2010 12:14 PM
  •  

    richbrownesq, SQLUSA,

     

    This is the output from @@VERSION:


    Microsoft SQL Server 2008 (SP1) - 10.0.2531.0 (X64)
     
    Mar 29 2009 10:11:52
     
    Copyright (c) 1988-2008 Microsoft Corporation
     
    Standard Edition (64-bit) on Windows NT 6.1 <X64> (Build 7600: ) (VM)


    We do not use stored procedures.


    IMPLICIT TRANSACTIONS is turned OFF:


    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 British
    set dateformat dmy
    set datefirst 1
    set transaction isolation level read committed


    The sysprocesses output interests me.

    Notice for SPID 54 there are two threads.

    kpid 1504 is waiting on ASYNC_NETWORK_IO

    kpid 5268 corresponds to the UPDATE (lastwaittype LCK_M_X)

    last_batch for kpid 1504 is 2010-10-29 09:37:39.863

    last_batch for kpid 5258 is 2010-07-06 12:58:04.907


    Thread 5268 has an open_tran count of 2.

    Both threads have status SUSPENDED.


    Could it be that the client has somehow "crashed" during the SELECT, yet SQL Server is still trying to send the
    results back to him (so we get the waittype ASYNC_NETWORK_IO, and we notice the wait time of this increasing).

    In the same block of our code, we then issue the UPDATE (without first checking the state of the SELECT thread).
    This then blocks on the first thread (and will forever block on this).


    We will do some more testing with the open transaction.


    Thank you.

     

    Friday, October 29, 2010 12:39 PM

  • We do not use stored procedures.

    It is best practices to use stored procedures.


    Kalman Toth, SQL Server & Business Intelligence Training; SQL 2008 GRAND SLAM
    Friday, October 29, 2010 3:22 PM
  • Hi macka001,

    Any progress?


    Regards,
    Tom Li
    Monday, November 1, 2010 6:09 AM