一個特殊的SQL Server阻塞案例分析

上周，在SQL Server數據庫下面遇到了一個有意思的SQL阻塞（SQL Blocking）案例。其實個人對SQL Server的阻塞還是頗有研究的。寫過好幾篇相關文章。 至於這里為什么要總結一下這個案例，因為這個案例有點意思：

 

 

1：使用DMV視圖捕獲到的Blocking SQL為一個查詢語句（這個不是真正引起阻塞的源頭SQL語句），等待事件為LCK_M_S。

 

2：出現阻塞的會話非常多，阻塞的量非常大，使用DMV視圖始終捕獲不到相關表的DML操作語句。捕獲到全是SELECT語句。

 

 

 

 

 

我們知道，在SQL Server中SELECT查詢是不會阻塞SELECT查詢的（不了解這個問題的，具體可以參考博客SQL Server中SELECT會真的阻塞SELECT嗎？ )。而且被阻塞的語句的等待類型為LCK_M_S，那么可以肯定：那個阻塞的源頭會話中，存在對該表的DML操作，而且事務由於某些原因未提交。只是那個會話最后執行的SQL語句為一個SELECT查詢。因為有時候，我們根本不能定位到SQL阻塞的源頭SQL語句，具體參考我的博客“為什么數據庫有時候不能定位阻塞（Blocker）源頭的SQL語句”，此處不做重復贅述。

 

我們用一個簡單的例子來模擬這個真實的案例，如需所示，首先創建一個測試表：

 

 

CREATE TABLE TEST (id    INT);
GO
INSERT INTO TEST VALUES(1);

 

 

 

然后再通過2個會話，模擬這樣的阻塞案例，如下所示：

 

 

會話A：

 

SET IMPLICIT_TRANSACTIONS ON;
GO
INSERT INTO TEST VALUES(2)
GO
SELECT  * FROM TEST WHERE ID =1;

 

 

 

注意：先設置開啟隱式事務，第一次執行插入數據語句，然后執行SELECT查詢。

 

   會話B：

 

 

SELECT * FROM TEST WHERE id=1;

 

 

   會話C:

 

 

SELECT wt.blocking_session_id                    AS BlockingSessesionId
      ,sp.program_name                        AS Blocking_ProgramName
      ,COALESCE(sp.LOGINAME, sp.nt_username)    AS Blocking_HostName
      ,ec1.client_net_address                    AS ClientIpAddress
      ,db.name                                AS DatabaseName
      ,wt.wait_type                            AS WaitType
      ,ec1.connect_time                        AS BlockingStartTime
      ,wt.WAIT_DURATION_MS/1000                AS WaitDuration
      ,ec1.session_id                            AS BlockedSessionId
      ,h1.TEXT                                AS BlockedSQLText
      ,h2.TEXT                                AS BlockingSQLText
FROM sys.dm_tran_locks  AS tl WITH(NOLOCK)
INNER JOIN sys.databases AS db  WITH(NOLOCK)
  ON db.database_id = tl.resource_database_id
INNER JOIN sys.dm_os_waiting_tasks AS wt  WITH(NOLOCK)
  ON tl.lock_owner_address = wt.resource_address
INNER JOIN sys.dm_exec_connections  ec1 WITH(NOLOCK)
  ON ec1.session_id = tl.request_session_id
INNER JOIN sys.dm_exec_connections  ec2 WITH(NOLOCK)
  ON ec2.session_id = wt.blocking_session_id
LEFT OUTER JOIN master.dbo.sysprocesses AS sp WITH(NOLOCK)
  ON SP.spid = wt.blocking_session_id
CROSS APPLY sys.dm_exec_sql_text(ec1.most_recent_sql_handle) AS h1
CROSS APPLY sys.dm_exec_sql_text(ec2.most_recent_sql_handle) AS h2

 

 

在會話C中查看SQL阻塞情況，如下截圖所示，我們看到是SELECT查詢阻塞了SELECT查詢。

 

 

 

如上測試所示，因為是構造模擬案例，開啟了“上帝視角”，所以你不會覺得有什么問題，實際情況是：應用程序是一個Java應用程序，而且是O/R Mapping框架（com.j256.ormlite），我將上面情況反饋給開發、Support人員，明確告訴他們阻塞的會話肯定有一個DML操作。讓他們查找定位代碼。但是諸多原因、因素疊加在一起（外包項目；溝通問題；對數據庫的阻塞的的理解），溝通的效果讓人很是無語。只能拿出確切的證據。由於那個框架開啟了隱性事務（事后跟蹤、分析發現的），而且UPDATE語句非常快，你使用DMV視圖定位到的阻塞源頭都是SELECT語句。顯然這個不是我想要的。

 

於是，我打算使用SQL Server Profiler里面的“Blocked process report”事件來定位阻塞的源頭，在跟蹤之前，修改'blocked process threshold (s)'的值。如下所示，

 

 

exec sp_configure 'show advanced options',1;

reconfigure with override

exec sp_configure 'blocked process threshold (s)',4

reconfigure with override

 

然后設置SQL Server Profiler的相關選項和過濾條件。就像我下面的測試的一樣，Blocked process report依然無法定位到阻塞的源頭SQL語句，如下所示：

 

 

 

 

<blocked-process-report monitorLoop="3262026">
 <blocked-process>
  <process id="process1f9b22ca8" taskpriority="0" logused="0" waitresource="RID: 1:1:574:1" waittime="10174" ownerId="2680347313" transactionname="SELECT" lasttranstarted="2018-11-26T14:09:55.130" XDES="0x123391a20" lockMode="S" schedulerid="2" kpid="8604" status="suspended" spid="104" sbid="0" ecid="0" priority="0" trancount="0" lastbatchstarted="2018-11-26T14:09:55.120" lastbatchcompleted="2018-11-26T14:09:37.887" lastattention="1900-01-01T00:00:00.887" clientapp="Microsoft SQL Server Management Studio - Query" hostname="GETNB00021" hostpid="10560" loginname="xxxx" isolationlevel="read committed (2)" xactid="2680347313" currentdb="1" lockTimeout="4294967295" clientoption1="671091040" clientoption2="390200">
   <executionStack>
    <frame line="1" stmtstart="24" stmtend="90" sqlhandle="0x02000000d8cd0821e4e62d2f8f098831e46f98ca20ba31ae0000000000000000000000000000000000000000"/>
    <frame line="1" stmtend="60" sqlhandle="0x0200000012eff610783e49a674c5361fd9c8bb38747a966a0000000000000000000000000000000000000000"/>
   </executionStack>
   <inputbuf>
SELECT  * FROM TEST WHERE ID =2;   </inputbuf>
  </process>
 </blocked-process>
 <blocking-process>
  <process status="sleeping" spid="89" sbid="0" ecid="0" priority="0" trancount="1" lastbatchstarted="2018-11-26T14:09:52.927" lastbatchcompleted="2018-11-26T14:09:52.927" lastattention="1900-01-01T00:00:00.927" clientapp="Microsoft SQL Server Management Studio - Query" hostname="GETNB00021" hostpid="10560" loginname="xxxx" isolationlevel="read committed (2)" xactid="2680346553" currentdb="1" lockTimeout="4294967295" clientoption1="671091040" clientoption2="390202">
   <executionStack/>
   <inputbuf>
SELECT  * FROM TEST WHERE ID =1;
   </inputbuf>
  </process>
 </blocking-process>
</blocked-process-report>

 

 

 

  

 

最后，只能使用SQL Server Profiler跟蹤某個登錄名（Login Name）一小段時間，根據會話ID一段時間內執行過的SQL來推理、判斷定位阻塞的源頭，從而找到具體原因，這個例子里面，ORM框架開啟了隱性事務，在SQL Server Profiler里面捕獲到開啟隱性事務以及UPDATE操作。至此。問題終於解開了謎底。當然本文不是按照當時的邏輯來寫的，而是在知道原因后，模擬構造案例重新的。所以總感覺字里行間寫不出那種味道。

 

SET IMPLICIT_TRANSACTIONS  ON;

 

.............

 

IF @@TRANCOUNT > 0 COMMIT TRAN set implicit_transactions off