什麼是等待

簡單說明一下什麼是等待：
當應用程式對SQL Server發起一個Session請求的時候，這個Session請求在資料庫中執行的過程中會申請其所需要的資源，
比如可能會申請記憶體資源，表上的鎖資源，物理IO資源，網路資源等等，
如果當前Session執行過程中需要申請的某些資源無法立即得到滿足，就會產生等待。
SQL Server會以不用的方式來展現這個等待資訊，比活動Session的等待資訊，例項級的等待資訊等等。
SQL Server中，等待事件是作為DBA進行TroubleShooting的重要參考資訊之一，SQL Server中可以通過多中方式來獲取等待資訊。

但是對於SQL Server 2016之前的版本來說，不管是活動Session級別的等待和例項級的等待，參考意義都有限，
更多的時候是想要更加詳細的且可以事後分析的等待，這就需要收集那些曾經已執行過的Session產生的等待資訊，也就是特定Session等待資訊的歷史記錄
本文重點介紹使用擴充套件事件來捕獲等待資訊，但不介紹擴充套件事件本身的使用，重點放在如何使用擴充套件事件來獲取想要的等待事件資訊。
需要對擴充套件事件有一定的瞭解。

等待資訊的獲取途徑

在SQL Server中有一個系統檢視sys.dm_os_wait_stats記錄了自資料庫服務啟動以來累積產生的等待資訊，
如下圖，這個結果是例項級的，也就是記錄的整個資料庫伺服器所有的等待事件的累積。
多數時候參考意義不是很大，比如某一天的網路延時很高，sys.dm_os_wait_stats中累計記錄了大量的ASYNC_NETWORK_IO等待資訊。
但是到了第二天或者什麼時候，網路變好了，但是sys.dm_os_wait_stats中記錄的ASYNC_NETWORK_IO等待資訊是不變的
也就是說sys.dm_os_wait_stats無法反映實時等待情況。

當然要獲取實時的等待資訊也簡單，記錄兩個時間點之間sys.dm_os_wait_stats中等待時間的差值，可以間接地反映出來某一段時間的資料的等待資訊。
但是這個資訊仍然比較粗略，依舊是例項級的，某些時候依舊是不足夠作為參考的。

另外一個是通過sys.dm_exec_requests這個系統檢視的wait_type，wait_time等獲取活動Session的等待資訊
如截圖，但是這個是活動Session的資訊，當Session完成之後，它的等待資訊就看不到曾經都產生了那些等待，分別是多久。
也就說，你無法追溯歷史上某一個Session或者某一個SQL（儲存過程）執行過程中的都產生了什麼型別的等待，等待了多長時間。

實話說，不管是sys.dm_os_wait_stats還是sys.dm_exec_requests，在正常情況下，獲取到的等待資訊實用價值都是不高或者是適用場景有限。

更多的時候我們是想要更細一級的等待，比如某一個Login、某一部分Session、甚至某些特定的SQL（儲存過程）的執行過程中產生的等待資訊。
舉個實際例子，資料庫又10個Login給10個不同的應用程式訪問，其中只有1個應用程式端反饋說訪問資料庫慢，或者有效能問題，其他Login都反饋正常
那麼很有可能是這個Login請求自己的問題，此時就需要針對這一個Login的情況進行鍼對性分析，而不是在例項級分析診斷。
如果能夠拿到這個Login執行的Session的等待情況，或者這個Login某些特定的資料庫物件的執行過程中的等待資訊，對定位問題的針對性的就比較強了。

本文就以此為切入點，針對如何獲取Session級別的等待資訊展開說明和演示。

SQL Server 2016中獲取Session級別的等待資訊

在SQL Server 2016中，獲取Session級別的等待資訊是比較方便的，有直接的系統檢視sys.dm_exec_session_wait_stats可以使用
當前情況下，想要知道某一個Session的等待資訊就很簡單了，
在sql語句開始的時候把當前Session的等待資訊記錄下來
在sql語句結束的時候把當前Session的等待資訊再次記錄出來
計算兩次等待資訊的差值，就可以知道當前Session執行的過程中有哪些等待，分別是多少。

　　sqlserver開發團隊可能也意識到了對於等待資訊，更多的時候，需要的是較為具體的等待，而不是一個籠統的例項級的等待
　　因此在SQL Server 2016中增加了sys.dm_exec_session_wait_stats這個支援統計Session級別的等待的檢視
　　很不幸的SQL Server2016之前的版本中是沒有這個系統檢視可以很方便地記錄Session級別的等待。
　　但是可以藉助擴充套件事件來實現類似的功能。

使用擴充套件事件來捕獲Session級別的等待資訊

因為這裡是是用擴充套件事件來實現的，這裡要求讀者要對擴充套件事件有一個基本的認識，擴充套件事件本身就不多說了。
上程式碼，啟動一個擴充套件事件，來記錄執行時間超過三秒的SQL語句，其執行過程中等待時間大於0的等待事件資訊。
當然這個捕獲的資訊可以加上各種過濾條件。具體參考程式碼備註。

IF EXISTS(SELECT * FROM sys.server_event_sessions WHERE name='SessionWaitStats')
  DROP EVENT session SessionWaitStats ON SERVER;
GO

--  建立事件會話  
CREATE EVENT SESSION SessionWaitStats ON SERVER   
ADD EVENT sqlserver.rpc_completed
(  
    ACTION
    (
        sqlos.task_time,
        sqlserver.database_name,
        sqlserver.nt_username,
        sqlserver.username,
        sqlserver.client_hostname,
        sqlserver.client_app_name,
        sqlserver.sql_text,
        sqlserver.session_id,
        sqlserver.transaction_id
    )  WHERE session_id>50 
        and [duration]>=3000000
),
--ADD EVENT sqlserver.sql_statement_completed
--(  
--    ACTION
--    (
--        sqlos.task_time,
--        sqlserver.database_name,
--        sqlserver.nt_username,
--        sqlserver.client_hostname,
--        sqlserver.client_app_name,
--        sqlserver.username,
--        sqlserver.sql_text,
--        sqlserver.session_id,
--        sqlserver.transaction_id
--    )  WHERE session_id>50 
--        and [duration]>=3000000
--),  
ADD EVENT sqlserver.sql_batch_completed
(  
    ACTION
    (
        sqlos.task_time,
        sqlserver.database_name,
        sqlserver.nt_username,
        sqlserver.client_hostname,
        sqlserver.client_app_name,
        sqlserver.username,
        sqlserver.sql_text,
        sqlserver.session_id,
        sqlserver.transaction_id
    ) WHERE session_id>50 
        and [duration]>=3000000
),
ADD EVENT sqlos.wait_info
(
    ACTION 
    (
        sqlos.task_time,
        sqlserver.database_name,
        sqlserver.nt_username,
        sqlserver.client_hostname,
        sqlserver.client_app_name,
        sqlserver.sql_text,
        sqlserver.username,
        sqlserver.session_id,
        sqlserver.transaction_id
    ) WHERE  session_id>50 
            and opcode=1 
            and duration>1
            and sql_text not like '%sp_MScdc_capture_job%'
            --and username = ''
),
ADD EVENT sqlos.wait_info_external
(
    ACTION
    (
        sqlos.task_time,
        sqlserver.database_name,
        sqlserver.nt_username,
        sqlserver.username,
        sqlserver.client_hostname,
        sqlserver.client_app_name,
        sqlserver.sql_text,
        sqlserver.session_id,
        sqlserver.transaction_id
    ) WHERE   session_id>50 
            and opcode=1 
            and duration>1
            and sql_text not like '%sp_MScdc_capture_job%'
            --and username = ''
)
ADD TARGET package0.event_file
(  
    SET filename=N'F:\XEvent Files\CollectionSessionWaitStats',
    max_file_size=(1024),   
    max_rollover_files=(10) 
)
WITH ( 
        MAX_MEMORY=4096 KB,            
        EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,
        MAX_DISPATCH_LATENCY=30 SECONDS,
        MAX_EVENT_SIZE=0 KB,            
        MEMORY_PARTITION_MODE=NONE,     
        TRACK_CAUSALITY=OFF,            
        STARTUP_STATE=ON
    )
GO

--  啟用（停止）事件會話（START / STOP）  
ALTER EVENT SESSION CollectionSessionWaitStats ON SERVER STATE=START  
GO

是用擴充套件事件收集的Session級別的等待資訊有以下幾個特點
1，SessionId是可以重複的
　　舉例說明就是:比如一個SessionId = 80的Session，可以第一次執行一個SQLA，第二次執行一個SQLB.
　　同時這兩個SQL的執行與其執行過程中產生的等待資訊都可以被捕獲出來
2，同一個時間段內，一個同一個SessionId不可能同時執行，
　　比如16：46：36秒到16：46：46秒到這個時間內，SessionId = 80的Session正在執行，擴充套件事件捕獲到了其產生的等待資訊
　　但是在16：46：36秒到16：46：46這個時間段內，不可能有另外一個SessionId = 80也在執行，這個邏輯不難理解
為什麼要特意說明這個問題？
因為擴充套件事件收集到的事件資訊中SQL語句完成事件（rpc_completed或者sql_batch_completed）與產生的等待之間，沒有一個直接的對應關係。

怎麼理解？動起手來才能發現問題，我是這個糾結了大半天，截圖示例。

如下截圖，擴充套件事件捕獲到的兩個目標事件的SessionId都是58，但是執行的SQL是不一樣的，

如下截圖是不區分事件型別，捕獲到的所有的事件資訊。

也就是上面說的，對於58號Session:
第一次運行了SELECT COUNT(1) FROM TestCollectionSessionWaitStats
第二次運行了SELECT COUNT(1) FROM TestCollectionSessionWaitStats WHERE Id>10
兩次執行的SQL一致或者不一致問題不大，關鍵是捕獲到的等待事件信心的SessionId也是58，怎麼區分產生的事件是歸屬於哪一次的執行？
比如58號Session執行兩次sql，產生了10條等待資訊，怎麼區分這10條等待資訊哪些歸屬於第一次執行生成的，哪些歸屬於第二次執行生成的？
這個就依靠上面說的第二點“同一個時間段內，一個同一個SessionId不可能同時執行”
對於同一個SessionId，在sql_batch_completed事件中，從時間的維度來看
小於第一次sql_batch_completed事件完成時間的必然是58號Session第一次執行生成的
大於第一次sql_batch_completed事件完成事件的且小於第二次sql_batch_completed的必然是58號Session第二次執行生成的
有了這個理論基礎，我們統計Session級別的等待就比較容易了，相信這個邏輯的實現並不難。

如下圖是58號Session執行某SQL語句產生的等待詳細資訊，可以看到多次產生了CXPACKET和 PAGEIOLATCH_SH等待
鑑於截圖問題，下面還有另外一個同樣是58號Session的執行另外一個SQL捕獲到的等待資訊
這個統計辦法就是上面提到的，在兩次sql_batch_completed事件中，雖然等待事件的SessionId一樣，
但是其發生的時候是處於當前事件的sql_batch_completed之前，上一次sql_batch_completed之後，
這樣就可以完美地匹配到sql_batch_completed事件與其對應的wait_info事件。
在這種情況下，統計得到類似於SQL Server 2016中的sys.dm_os_wait_stats的結果也就不難了。

與sys.dm_os_wait_stats 等待資訊的結果相比，上述通過擴充套件事件獲取的等待資訊，是不是更加詳細和具體？
比如對於CXPACKET等待時間，
不難發現，如果計算計算其產生的次數（count），就類似於sys.dm_os_wait_stats 中的waiting_tasks_count，計算其產生的總時間（sum），就類似於wait_time_ms
但是上述時間的資訊已經細化到Session級別了，比sys.dm_os_wait_stats 中的等待資訊更有參考價值。
對於問題的診斷和分析，也會是更加有效。

　　補一張實際測試出來的資訊，分別是Session的執行資訊（SessionId+登入名+SQL語句+消耗時間+完成時間）對應的等待資訊（等待型別+等待次數+等待時間），
　　是不是幾乎完全類似於sys.dm_exec_session_wait_stats中統計出來的結果。

上述統計結果的SQL語句

/*

SELECT event_table.xml_event_data
FROM (
        SELECT CAST(event_data AS XML) xml_event_data 
        FROM sys.fn_xe_file_target_read_file(N'F:\XEvent Files\CollectionSessionWaitStats*', NULL, NULL, NULL)
    ) AS event_table
    CROSS APPLY xml_event_data.nodes('//event') n (event_xml)
WHERE  event_xml.value('(./@name)', 'varchar(1000)') IN ('rpc_completed','sql_batch_completed','sql_statement_completed')

*/


-- Parse the XML to show rpc_completed,sql_batch_completed details
if object_id('tempdb..#t1') is not null
    drop table #t1
SELECT
    event_xml.value('(./action[@name="session_id"]/value)[1]', 'INT') as session_id,
    event_xml.value('(./@timestamp)', 'varchar(1000)') as timestamp,
    event_xml.value('(./action[@name="sql_text"]/value)[1]', 'varchar(max)') as sql_text,
    event_xml.value('(./action[@name="client_hostname"]/value)[1]', 'varchar(max)') as client_hostname,
    event_xml.value('(./action[@name="client_app_name"]/value)[1]', 'varchar(max)') as client_app_name,
    event_xml.value('(./@name)', 'varchar(1000)') as Event_Name,
    event_xml.value('(./data[@name="duration"]/value)[1]', 'bigint') as Duration,
    event_xml.value('(./data[@name="cpu_time"]/value)[1]', 'bigint') as cpu_time,
    event_xml.value('(./data[@name="physical_reads"]/value)[1]', 'bigint') as physical_reads,
    event_xml.value('(./data[@name="logical_reads"]/value)[1]', 'bigint') as logical_reads,
    event_xml.value('(./action[@name="username"]/value)[1]', 'varchar(max)') as username
INTO #t1
FROM (
        SELECT CAST(event_data AS XML) xml_event_data 
        FROM sys.fn_xe_file_target_read_file(N'F:\XEvent Files\SessionWaitStats*', NULL, NULL, NULL)
     ) AS event_table
CROSS APPLY xml_event_data.nodes('//event') n (event_xml)
WHERE event_xml.value('(./@name)', 'varchar(1000)')  in ('rpc_completed','sql_batch_completed','sql_statement_completed')
order by Event_Name




-- Parse the XML to show wait_info,wait_info_external details
if object_id('tempdb..#t2') is not null
    drop table #t2
SELECT 
    cast(event_xml.value('(./@timestamp)', 'varchar(1000)') as DATETIME2) as timestamp,
    event_xml.value('(./data[@name="duration"]/value)[1]', 'bigint') as duration,
    event_xml.value('(./action[@name="session_id"]/value)[1]', 'INT') as session_id,
    event_xml.value('(./data[@name="wait_type"]/text)[1]', 'VARCHAR(200)') as wait_type
INTO #t2
FROM (
        SELECT CAST(event_data AS XML) xml_event_data 
        FROM sys.fn_xe_file_target_read_file(N'F:\XEvent Files\SessionWaitStats*', NULL, NULL, NULL)
     ) AS event_table
     CROSS APPLY xml_event_data.nodes('//event') n (event_xml)
WHERE event_xml.value('(./@name)', 'varchar(1000)')  in ('wait_info','wait_info_external')



if object_id('tempdb..#t3') is not null
    drop table #t3

SELECT 
    a.session_id                    AS SessionId,
    a.sql_text                        AS SqlText,
    a.username                        AS UserName,
    a.client_hostname                AS ClientHostname,
    a.client_app_name                as ClientAppName,
    a.Duration                        AS TotalExecuteTime,
    CAST(a.timestamp AS DATETIME2)    AS CompletedTime,
    CAST(b.timestamp AS DATETIME2)    AS WaitTypeStartTime,
    b.wait_type                        AS WaitType,
    b.duration                        AS WaitDuration
INTO #t3
FROM #t1 a INNER JOIN #t2 b on a.session_id = b.session_id
    and b.timestamp < a.timestamp 
    and b.timestamp > (
                         select top 1 timestamp from #t1 c 
                         where a.session_id = a.session_id and a.timestamp > b.timestamp
                         order by a.timestamp
                     )



if object_id('tempdb..#t4') is not null
    drop table #t4

SELECT    DISTINCT
        SessionId            ,
        UserName            ,
        SqlText                ,
        TotalExecuteTime    ,
        CompletedTime        ,
        WaitType            ,
        COUNT(WaitType)    over(partition by SessionId,SqlText,TotalExecuteTime,CompletedTime) WaitTypeCOUNT,
        SUM(WaitDuration)   over(partition by SessionId,SqlText,TotalExecuteTime,CompletedTime) WaitTypeTimes
INTO #t4
FROM #t3


SELECT  CASE WHEN t.Rn = 1 THEN  CAST(SessionId AS VARCHAR(20))    ELSE '' END AS SessionId,
        CASE WHEN t.Rn = 1 THEN  UserName    ELSE '' END AS UserName,
        CASE WHEN t.Rn = 1 THEN  SqlText    ELSE '' END AS SqlText,
        CASE WHEN t.Rn = 1 THEN  TotalExecuteTime ELSE '' END AS TotalExecuteTime,
        CASE WHEN t.Rn = 1 THEN  CAST(CompletedTime AS VARCHAR(20))    ELSE '' END AS CompletedTime,
        WaitType            ,
        WaitTypeCOUNT        ,
        WaitTypeTimes
FROM 
(
    SELECT 
    ROW_NUMBER()OVER(PARTITION BY SessionId,CompletedTime ORDER BY CompletedTime) AS Rn,*
    FROM #t4
)t

當然該語句僅供參考，目的是為了收集Session級的統計資訊，當收集到Session級別的統計資訊之後，具體的統計方式也不難。

總結
　　　等待事件可以幫助我們診斷SQL Server上的一些資源瓶頸，對於問題的處理和解決有著比較重要的參考意義，如果能夠細化地收集等待事件，對於解決問題的參考意義會更大。
　　　本文通過一個簡單的示例，使用擴充套件事件來收集SQL Server中一些特定場景下的等待資訊，來更加有針對性地進行問題的診斷和識別，使得問題的分析更加高效和具有針對性。