1. 程式人生 > >SQL Server擴充套件事件的使用ring_buffer target時“丟失”事件的原因分析以及ring_buffer target潛在的問題

SQL Server擴充套件事件的使用ring_buffer target時“丟失”事件的原因分析以及ring_buffer target潛在的問題

事情起因:
  排查SQL Server上的死鎖問題,一開始想到的就是擴充套件事件,
  第一種方案,開profile守株待兔吧,顯得太low了,至於profile的變種trace吧,垂垂老矣,也一直沒怎麼用過。
  第二種方案是開啟TRACE flag(DBCC TRACEON (3605,1204,1222,-1))將死鎖寫入error log,也是個不錯的選擇。
  不過想到系統預設的擴充套件事件system_health已經捕獲了死鎖資訊(sqlserver.xml_deadlock_report),
  就沒必要再重新往error log記一次了,理論上從system_health中就能拿到死鎖資訊,因此嘗試從system_health的ring_buffer target獲取死鎖資訊。

排查經過:
  從sysem_health的ring_buffer中目標中,並沒有捕獲到預期的曾經發生的死鎖事件資訊,
  在完全確認發生過死鎖的情況下(並且是最近,或者是剛剛),為什麼sysem_health“沒有能夠捕獲到”?
  無奈之下單獨開了一個捕獲死鎖事件的擴充套件事件Session(僅捕獲sqlserver.xml_deadlock_report),target目標是儲存在ring_buffer中
  在人為刻意地製造一個死鎖之後,來檢驗sysem_health和自定義的捕獲擴充套件事件捕獲的死鎖資訊
  此時意想不到的情況發生了,自定義的擴充套件事件完整地捕獲到了這個死鎖資訊,而system_health仍舊沒有捕獲到對應的死鎖資訊。
  什麼情況?

   如下自定義擴充套件事件指令碼

CREATE EVENT SESSION [Deadlock_Monitor] ON SERVER
ADD EVENT sqlserver.xml_deadlock_report
ADD TARGET package0.ring_buffer(SET max_events_limit=(5000),max_memory=(4096))
WITH
(MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=10 SECONDS,
MAX_EVENT_SIZE
=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,STARTUP_STATE=ON) ALTER EVENT SESSION [Deadlock_Monitor] ON SERVER STATE = start;

死鎖捕獲結果,sysem_health並沒有捕獲到預期的死鎖事件,儘管他包括了sqlserver.xml_deadlock_report事件

SELECT  xed.value('@timestamp', 'datetime') AS Creation_Date ,
        CAST(REPLACE(REPLACE(REPLACE(CAST(xed.query('.') AS NVARCHAR(MAX)),'&lt;', '<'),'&gt;', '>'),'&amp;apos;','''') AS xml) AS Extend_Event
FROM    ( SELECT    CAST([target_data] AS XML) AS Target_Data
          FROM      sys.dm_xe_session_targets AS xt
                    INNER JOIN sys.dm_xe_sessions AS xs ON xs.address = xt.event_session_address
          WHERE     xs.name = N'system_health'
                    AND xt.target_name = N'ring_buffer'
        ) AS XML_Data
        CROSS APPLY Target_Data.nodes('RingBufferTarget/event[@name="xml_deadlock_report"]')
        AS XEventData ( xed )
ORDER BY Creation_Date DESC

select * from sys.dm_xe_session_targets

SELECT    CAST([target_data] AS XML) AS Target_Data
FROM      sys.dm_xe_session_targets AS xt
                    INNER JOIN sys.dm_xe_sessions AS xs ON xs.address = xt.event_session_address
WHERE     xs.name = N'system_health'
          --AND xt.target_name = N'ring_buffer'

-- Parse the XML to show wait details
SELECT event_table.*
    FROM (
        SELECT CAST(event_data AS XML) xml_event_data 
        FROM sys.fn_xe_file_target_read_file(N'path\Log\system_health*', NULL, NULL, NULL)
    ) AS event_table
    CROSS APPLY xml_event_data.nodes('//event') n (event_xml)
WHERE  event_xml.value('(./@name)', 'varchar(1000)') IN ('xml_deadlock_report')   

  由於sysem_health有兩個輸出的target,一個ring_buffer,一個是target_file,無奈下從event_file查詢捕獲的死鎖資訊,這裡又是沒問題的,正常捕獲到了。

  

  因此就可以說,系統預設自帶的sysem_health擴充套件事件,捕獲死鎖本身是沒有問題的,問題出在擴充套件事件的輸出目標ring_buffer上。
  在不過濾所有的擴充套件事件情況下,從ring_buffer裡面解析出來的資料還有個特點,其不包含最近一段時間的任何一種事件資訊。
  也就是說,ring_buffer中解出來的事件資訊,是當前時間前一段時間的事件資訊,並不包含所有的事件資訊,以及最近一段事件所有的事件資訊。
  當然你可以說ring_buffer是先進先出的佇列模型,那也應該留下新的事件,而不是解析不出來最新的事件資訊。

原因分析:
  參考了sqlskill上的一篇文章,這篇文章深入地解析了這個問題,
  簡單說就是:
  ring_buffer並沒有“丟失”事件資訊,至於為什麼解析不出來,要從ring_buffer解析方式開始,ring_buffer擴充套件事件從sys.dm_xe_session_targets 這個DMV中解析的,
  受到sys.dm_xe_session_targets 這個DMV的目標資料列target_data欄位只能容納大約4 MB的XML資料的限制。
  當ring_buffer捕獲的事件(記憶體中的二進位制資料)轉換為XML格式大於(大約)4MB的情況下,超過4MB的其他的事件會被被“截斷”,
  從sys.dm_xe_session_targets解析出來的XML檔案優先輸出更早的事件,所以我們預期下的最近發生的事件是無法看到的。
  因此,正如上文中遇到的情況一樣:“丟失”部分事件資訊,並且沒有最近的事件資訊。

總結:  
  以此來看,使用ring_buffer為擴充套件事件的target,潛在以下問題
  1,解析出來的結果並不可靠(完整),可能無法解析到最近的部分事件。
  2,以下譯文中還會提到,ring_buffer作為target可能會撐爆記憶體的情況,所以要謹慎使用。
  3,同樣下文會提到,SSMS的UI對ring_buffer中的事件支援的並不好,對於ring_buffer的target,UI也僅僅是show出來一個XML檔案,必須要自己解析,而不像event_file中那樣表格化展示(可讀性)
  因此要儘量避免在擴充套件事件中使用ring_buffer target。

(標題)我為什麼討厭擴充套件事件中的ring_buffer target

我曾經多次遇到擴充套件事件中有關ring_buffer target同樣的問題,
我想我會寫一篇部落格文章,解釋了我教的所有資訊關於ring_buffer target和與之關聯的問題。
自從sqlserver 2012釋出以及擴充套件事件新UI的更新,我以後堅決不會再使用ring_buffer target
事實上,正如文章標題所言,我確實很討厭ring_buffer target,這篇文章中我將會闡述我討厭ring_buffer target的原因,並且希望說服應該使用file_target代替。

丟失事件

這是我通過電子郵件解釋關於ring_buffer目標的最常見問題。一般來說,如下是典型的問題描述:

我從SQL Server中心的一篇文章中得到了下面的程式碼,它不起作用。我遇到的問題是,當我執行程式碼時,即使我知道應用程式中剛剛發生了一個死鎖事件,它也不會顯示任何死鎖資訊。
似乎我只在system_health會話中看到較舊的死鎖,但從來沒有看到最新的死鎖。我打開了Trace 1222並以這種方式獲取資訊,那麼為什麼不這樣做。

實際情況是,事件(event)實際上在就那裡,你無法看到(你預期的事件)是因為sys.dm_xe_session_targets 這個DMV的限制。
這個DMV的目標資料列只能輸出大約4 MB的XML資料。
Bob Ward20009年的時候在CSS SQL Server工程師部落格中解釋了DMV的4 MB格式XML限制的資訊。
為了證明這種限制的結果,讓我們來看看在SQL Server 2012 SP1+CU7伺服器上的系統健康事件會話中包含的事件數量,我可以使用下面的查詢來檢視資訊。

SELECT
    ring_buffer_event_count, 
    event_node_count, 
    ring_buffer_event_count - event_node_count AS events_not_in_xml
FROM
(    SELECT target_data.value('(RingBufferTarget/@eventCount)[1]', 'int') AS ring_buffer_event_count,
        target_data.value('count(RingBufferTarget/event)', 'int') as event_node_count
    FROM
    (    SELECT CAST(target_data AS XML) AS target_data  
        FROM sys.dm_xe_sessions as s
        INNER JOIN sys.dm_xe_session_targets AS st 
            ON s.address = st.event_session_address
        WHERE s.name = N'system_health'
            AND st.target_name = N'ring_buffer'    ) AS n    ) AS t;

image

ring_buffer_event_count是RingBufferTarget根元素返回的XML文件的eventCount屬性(譯者注:ring_buffer_event_count是RingBufferTarget捕獲到的事件的總數)
event_node_count是sys.dm_xe_session_targets 這個 DMV中返回的ingBufferTarget/event nodes中事件的個數(兩者的差值就是所謂丟失的事件個數)
這裡你可以看到ring_buffer target中一共有5000個事件,(原因是)system_health會話基於2012新的MAX_EVENTS_LIMIT選項設定在5000。
不過,僅僅有3574個事件被DMV中的XML輸出了出來,剩下有1426個事件仍然不可用(不可見,無法解析出來),儘管他們是滯留在記憶體中的。
sys.dm_xe_session_targets 的XML檔案優先輸出更早的事件,所以我們預期下的最近發生的事件是無法看到的。

譯者注,如下是system_health中ring_buffer MAX_EVENTS_LIMIT選項設定在5000的值:

我們可以觀察擴充套件事件目標占用的記憶體和DMV中的XML二進位制資料佔用的記憶體情況,使用如下查詢

SELECT
    target_data.value('(RingBufferTarget/@memoryUsed)[1]', 'int') AS buffer_memory_used_bytes,
    ROUND(target_data.value('(RingBufferTarget/@memoryUsed)[1]', 'int')/1024., 1) AS buffer_memory_used_kb,
    ROUND(target_data.value('(RingBufferTarget/@memoryUsed)[1]', 'int')/1024/1024., 1) AS buffer_memory_used_MB,
    DATALENGTH(target_data) AS xml_length_bytes,
    ROUND(DATALENGTH(target_data)/1024., 1) AS xml_length_kb,
    ROUND(DATALENGTH(target_data)/1024./1024,1) AS xml_length_MB
FROM (
SELECT CAST(target_data AS XML) AS target_data  
FROM sys.dm_xe_sessions as s
INNER JOIN sys.dm_xe_session_targets AS st 
    ON s.address = st.event_session_address
WHERE s.name = N'system_health'
 AND st.target_name = N'ring_buffer') as tab(target_data)

這裡我們可以看到,二進位制資料佔用的記憶體大約為1.7MB,不過一旦序列化為XML,檔案的大小就變為大約4.7MB,比二進位制資料空間要大
問題的本質就在於,擴充套件事件生成的特點,決定了他緊湊的二進位制格式的,但是序列化的格式化XML會為這些事件增加儲存空間。

system_health事件會話特別傾向於收集最多5000個事件但ring_buffer,DMV實際上只能輸出一小部分事件會話。
最有可能的是,sp_server_diagnostics_component_output和xml_deadlock_report具有相當大的事件是(佔用的空間),因為這兩個事件返回的XML的大小取決於它們何時觸發的條件的具體情況。

我發現在繁忙的伺服器上出現問題時,sp_server_diagnostics_component_output事件的大小超過了512KB,
因此當輸出XML中包含其中一個事件時,對ring_buffer目標,由DMV返回的資料可能會受到很大限制。

沒有UI的支援

這對我來說可能是我日常工作中不再使用ring_buffer作為輸出目標的最大原因。
擴充套件事件UI不支援分解ring_buffer目標中包含的資訊, UI的唯一功能是顯示由sys.dm_xe_session_targets DMV的target_data列輸出的XML。

image

這意味著要使用資料,您必須開啟XML並掃描事件,或編寫XQuery以將XML解析為表格形式,這要求您知道事件會話中使用的事件,列和操作定義來真正訪問資料。
如果我正在進行短期資料收集,並且不希望它儲存到SQL Server 2012上的檔案系統中的檔案,我只需選擇實時檢視就可以將資料流式傳輸回UI的列表中,
在這種情況下,我不必處理XML並可以快速找到我感興趣的資訊。
對於任何長期任務,甚至檢視system_health事件會話中的資訊,我都使用file_target,UI可以讀取和處理事件,無需手動執行任何XQuery。

當心記憶體的使用

在生產伺服器上配置ring_buffer目標的方式需要非常小心,這對我來說是前所未聞的。
兩週之前,Andy Galbraith遇到一個所有連線報701系統記憶體不足的錯誤,
經過分析,Andy發現在記憶體16GB,最大記憶體(max server memory)配置為11000MB的伺服器上,MEMORYCLERK_XE memory clerk 佔用了10GB的記憶體,
問題就在於,一個擴充套件事件配置了收集最大(MAX_EVENTS_LIMIT)1,000,000 個事件,但是沒有配置最大記憶體限制,
因此記憶體的使用就基於擴充套件事件收集到的事件個數,並且沒有最大的記憶體使用限制,那麼它就可以使用無限的記憶體,在記憶體有限的情況下,從而導致伺服器上出現問題。