446
MSSQL· 實現分析 · Extend Event日誌文件的分析方法
背景
在前兩篇月報分享中，6月份月報我們分享了SQL Server實現審計日誌功能的方法探索，最終從可靠性、對象級別、可維護性、開銷和對數據庫係統影響五個方麵得出最佳選項Extend Event；7月份月報我們量化分析了使用Extend Event實現審計日誌功能對SQL Server本身的性能和吞吐量的影響，結論是對係統性能和吞吐量影響均在0.01%左右；8月份的月報分享是SQL Server審計日誌專題的最後一期，探討Extend Event實現審計日誌功能的分析方法匯總，以及這些方法的優缺點。
6月份月報，詳情請戳：MSSQL · 實現分析 · SQL Server實現審計日誌的方案探索
7月份月報，詳情請戳：MSSQL · 實現分析 · Extend Event實現審計日誌對SQL Server性能影響
問題引入
為了兼容SQL Server 2008R2版本，我們稍微對實現審計日誌功能的擴展事件創建方法稍微修改如下：
USE master
GO
CREATE EVENT SESSION [svrXEvent_User_Define_Testing] ON SERVER
ADD EVENT sqlserver.sql_statement_completed
(
ACTION
(
sqlserver.database_id,
sqlserver.session_id,
sqlserver.username,
sqlserver.client_hostname,
sqlserver.client_app_name,
sqlserver.sql_text,
sqlserver.plan_handle,
sqlserver.tsql_stack,
sqlserver.is_system,
package0.collect_system_time
)
WHERE sqlserver.username <> N'NT AUTHORITY\SYSTEM'
AND sqlserver.username <> 'sa'
AND sqlserver.is_system = 0
)
ADD TARGET package0.asynchronous_file_target
(
SET
FILENAME = N'C:\Temp\svrXEvent_User_Define_Testing.xel',
METADATAFILE = N'C:\Temp\svrXEvent_User_Define_Testing.xem',
MAX_FILE_SIZE = 10,
MAX_ROLLOVER_FILES = 500
)
WITH (
EVENT_RETENTION_MODE = NO_EVENT_LOSS,
MAX_DISPATCH_LATENCY = 5 SECONDS,
STARTUP_STATE=ON
);
GO
-- We need to enable event session to capture event and event data
ALTER EVENT SESSION [svrXEvent_User_Define_Testing]
ON SERVER STATE = START;
GO
擴展事件創建完畢並啟動以後，發生在SQL Server數據庫服務端的所有sql_statement_completed事件信息都會被擴展事件異步滾動記錄在日誌文件svrXEvent_User_Define_Testing.xel文件中，日誌文件格式是svrXEvent_User_Define_Testing_0_TimeStamp.xel，比如svrXEvent_User_Define_Testing_0_131465070445690000.xel。這裏就引入了這期月報分享的重點問題了：
審計日誌有哪些分析方法
這些方法各自的優缺點是什麼
我們該如何選擇哪種適用的方法
使用DMF
SQL Server擴展事件（Extend Event，簡稱為XE）采用異步的方式將審計日誌記錄寫入目標日誌文件中，且每個事件以XML格式單行寫入日誌文件，因此我們可以采用SQL Server提供的動態管理函數sys.fn_xe_file_target_read_file來讀取和分析升級日誌文件。
全量讀取
全量審計日誌讀取是指使用SQL Server DMF sys.fn_xe_file_target_read_file ( path, mdpath, initial_file_name, initial_offset ) 中，不傳入initial_file_name和initial_offset。這種方法讀取的是審計日誌目錄下所有的審計日誌文件中的內容。比如，以下是使用DMF全量讀取所有審計日誌文件記錄的例子：
USE master
GO
SELECT *
FROM sys.fn_xe_file_target_read_file('C:\Temp\svrXEvent_User_Define_Testing*.xel',
'C:\Temp\svrXEvent_User_Define_Testing*.xem', null, null)
展示的結果如下：
從這個結果來看，我們無法明確的知道哪個用戶在哪個時間點執行了哪些SQL語句，執行耗時多少等更為詳細有價值的信息。這裏我們需要采用XML解析的方法來分析Event_data字段中更為豐富的內容。請使用下麵的查詢語句獲取更為詳細的信息：
-- This is SQL 2008R2
;WITH events_cte
AS (
SELECT
[event_data] = T.C.query('.'),
[event_name] = T.C.value('(event/@name)[1]','varchar(100)'),
[event_time] = DATEADD(mi, DATEDIFF(mi, GETUTCDATE(), CURRENT_TIMESTAMP),T.C.value('(event/@timestamp)[1]','datetime2')),
[client app name] = T.C.value('(event/action[@name="client_app_name"]/value/text())[1]', 'sysname'),
[client host name] = T.C.value('(event/action[@name="client_hostname"]/value/text())[1]', 'sysname'),
[database_id]= T.C.value('(event/action[@name="database_id"]/value/text())[1]', 'int'),
[cpu time (ms)] = T.C.value('(event/data[@name="cpu"]/value/text())[1]', 'bigint'),
[logical reads] = T.C.value('(event/data[@name="reads"]/value/text())[1]', 'bigint'),
[logical writes] = T.C.value('(event/data[@name="writes"]/value/text())[1]', 'bigint'),
[duration (ms)] = T.C.value('(event/data[@name="duration"]/value/text())[1]', 'bigint'),
[row count] = T.C.value('(event/data[@name="row_count"]/value/text())[1]', 'bigint'),
[sql_text] = T.C.value('(event/action[@name="sql_text"]/value/text())[1]','nvarchar(max)'),
[session_id] = T.C.value('(event/action[@name="session_id"]/value/text())[1]','int'),
[user_name] = T.C.value('(event/action[@name="username"]/value/text())[1]','sysname'),
[is_system] = T.C.value('(event/action[@name="is_system"]/value/text())[1]','sysname'),
[query_timestamp] = T.C.value('(event/action[@name="collect_system_time"]/value/text())[1]','bigint'),
[query_time] = DATEADD(mi, DATEDIFF(mi, GETUTCDATE(), CURRENT_TIMESTAMP),T.C.value('(event/action[@name="collect_system_time"]/text/text())[1]','datetime2'))
FROM sys.fn_xe_file_target_read_file('C:\Temp\svrXEvent_User_Define_Testing*.xel',
'C:\Temp\svrXEvent_User_Define_Testing*.xem', null, null)
CROSS APPLY (SELECT CAST(event_data as XML) AS event_data) as T(C)
)
SELECT
cte.session_id,
--cte.query_timestamp,
--cte.[event_time],
cte.[query_time],
--cte.[event_name],
cte.user_name,
[database_name] = db.name,
cte.[database_id],
cte.[client host name],
cte.[logical reads],
cte.[logical writes],
cte.[cpu time (ms)],
cte.[duration (ms)],
--cte.[plan_handle],
cte.sql_text,
sql_text_hash = CHECKSUM(cte.sql_text),
cte.[client app name],
cte.[event_data],
cte.is_system
FROM events_cte as cte
LEFT JOIN sys.databases as db
on cte.database_id = db.database_id
ORDER BY [query_time] ASC
;
執行結果展示如下：
從這個結果集中，我們可以很清楚的知道每一條SQL語句執行的詳細情況，包括：用戶名、執行時間點、客戶機名、邏輯讀、邏輯寫、CPU消耗、執行時間消耗、查詢語句詳情等非常重要的信息。
部分讀取
使用DMF sys.fn_xe_file_target_read_file ( path, mdpath, initial_file_name, initial_offset )實現審計日誌除了全量讀取外，還可以實現部分讀取，我可以傳入initial_file_name和initial_offset來實現從某個日誌文件的特定offset（文件內容偏移量）開始讀取。以此來減小每次讀取審計日誌文件的大小。比如，我們從文件C:\Temp\svrXEvent_User_Define_Testing_0_131471065758970000.xel中的偏移量為開始94720開始讀取，執行方法如下：
USE master
GO
SELECT *
FROM sys.fn_xe_file_target_read_file('C:\Temp\svrXEvent_User_Define_Testing*.xel',
'C:\Temp\svrXEvent_User_Define_Testing*.xem', 'C:\Temp\svrXEvent_User_Define_Testing_0_131471065758970000.xel', 94720)
執行結果截圖如下：
當然，你也可以使用“全量讀取”中的分析方法來獲取部分讀取到的審計日誌詳細信息，在此不再累述。
XEReader API
我們除了使用SQL Server本身提高的DMF來分析審計日誌以外，還可以使用XE Reader API，通過編程的方式來讀取審計日誌文件。從SQL Server 2012開始，在Shared（C:\Program Files\Microsoft SQL Server\110\Shared）目錄下，提供了XEvent相關的兩個dll文件，可以使用XEReader的API接口來讀取審計日誌文件。
SQL 2012: Microsoft.SqlServer.XEvent.Linq.dll
SQL 2014: Microsoft.SqlServer.XEvent.Linq.dll和Microsoft.SqlServer.XE.Core.dll
SQL 2016: Microsoft.SqlServer.XEvent.Linq.dll和Microsoft.SqlServer.XE.Core.dll
以下是Visual Studio 2015編程工具，使用C#編程語言，編寫的控製台應用程序項目，來詳細看看如何使用XEReader API來實現分析審計日誌文件。
using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;
using System.Threading.Tasks;
using Microsoft.SqlServer.XEvent.Linq;
namespace MonthlyShareExtendEventDemo
{
class Program
{
static void Main(string[] args)
{
string[] xelFiles = new string[] { @"C:\Temp\svrXEvent_User_Define_Testing*.xel" };
string[] xemFiles = new string[] { @"C:\Temp\svrXEvent_User_Define_Testing*.xem" };
QueryableXEventData events = new QueryableXEventData(xelFiles, xemFiles);
foreach (PublishedEvent evt in events)
{
Console.WriteLine("=>>>>>>>>>>>>>>>>>>" + evt.Name);
foreach (PublishedEventField fld in evt.Fields)
{
Console.WriteLine("\tField: {0} = {1}", fld.Name, fld.Value);
}
foreach (PublishedAction act in evt.Actions)
{
Console.WriteLine("\tAction: {0} = {1}", act.Name, act.Value);
}
Console.WriteLine("=<<<<<<<<<<<<<<<" + evt.Name);
}
Console.ReadKey();
}
}
}
我截圖其中一條得到的審計日誌如下圖所示：
注意：
在使用XEReader API分析審計日誌，需要依賴兩個安裝包：SQLSysClrTypes.msi和SharedManagementObjects.msi，請提前安裝完畢。
事件流讀取
當然我們也可以采用XEReader API事件流的方式讀取審計日誌，當客戶端有查詢語句提交到SQL Server 後台服務，事件流會捕獲到這個查詢行為，並加以分析。事例代碼如下：
using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;
using System.Threading.Tasks;
using Microsoft.SqlServer.XEvent.Linq;
namespace XEStreamDemo
{
class Program
{
static void Main(string[] args)
{
string connString = string.Format("Data Source=.,{0};Initial Catalog={1};Integrated Security=SSPI", 1433, "master");
string xeSessionName = @"svrXEvent_User_Define_Testing";
using (QueryableXEventData eventData = new QueryableXEventData(connString, xeSessionName, EventStreamSourceOptions.EventStream, EventStreamCacheOptions.DoNotCache))
{
foreach (PublishedEvent evt in eventData)
{
Console.WriteLine("=>>>>>>>>>>>>>>>>>>" + evt.Name);
foreach (PublishedEventField fld in evt.Fields)
{
Console.WriteLine("\tField: {0} = {1}", fld.Name, fld.Value);
}
foreach (PublishedAction act in evt.Actions)
{
Console.WriteLine("\tAction: {0} = {1}", act.Name, act.Value);
}
Console.WriteLine("=<<<<<<<<<<<<<<<" + evt.Name);
}
}
Console.ReadKey();
}
}
}
當執行查詢的時候，這個控製台應用程序會捕獲到SQL Server 服務端執行的查詢語句，如下截圖：
注意：
基於事件流分析SQL Server審計日誌功能的方法不支持SQL Server 2008以及SQL Server 2008R2版本，最低的版本要求是SQL Server 2012。因為在SQL Server 2012以下版本中會報告“Invalid object name ‘sys.fn_MSxe_read_event_stream”異常信息，錯誤信息如下所示。
An unhandled exception of type ‘System.Data.SqlClient.SqlException’ occurred in System.Data.dll
Additional information: Invalid object name ‘sys.fn_MSxe_read_event_stream’.
異常信息截圖如下：
三種方法對比
這一章節介紹三種審計日誌分析方法的對比，我們將會從以下幾個角度來衡量這三種方法：
是否依賴SQL Server Service
分析延遲性
穩定性
對SQL Server的影響
DMF
DMF sys.fn_xe_file_target_read_file是SQL Server本身內置的對象，所以使用這種方法分析審計日誌信息，無需過多的編程處理，門檻較低，甚至可以直接使用SSMS都可以分析審計日誌文件。這些是使用DMF分析審計日誌的優點。當然，這個方法的缺點也很明顯：使用DMF方式讀取審計日誌，需要連接到SQL Server服務，所以要求SQL Server服務本身是啟動的，因為這個是使用SQL Server內置的動態管理函數來實現的；而且這種分析方法需要使用SQL Server對XML操作技術來解析event_data，解析XML是一個CPU密集型操作，非常消耗係統CPU資源。在我之前的測試案例中，使用DMF方法分析審計日誌詳情導致了50%多的額外CPU開銷。如下截圖所示：
XEReader API
使用SQL Server XEReader提供的API讀取審計日誌文件的方法，完全是基於審計日誌文件的操作方式，可以獨立於SQL Server的服務。換句話說，不管SQL Server是處於關閉還是啟動狀態，對我們審計日誌的分析不會受到任何影響。這些是使用XEReader API分析審計日誌的優點。而這個方法也有它的缺點：當我們分析當前（正在被Extend Event Session對象寫入的日誌文件）審計日誌文件時，我們不知道（或者很難知道）哪些記錄是我們分析過的，哪些是還未分析的？如果這個問題解決不了的話，很可能就會導致審計日誌記錄的重複或者丟失。當然，我們也可以采用XE循環寫入審計日誌文件的方法，每次讀取Archive出來的審計日誌文件，跳過當前文件的讀取，等待當前文件寫滿固定大小，Archive出來以後，再來讀取分析。這個改進方法會引入另外一個問題是，可能會導致審計日誌的分析延遲，而且延遲的時間還不確定。比如：用戶查詢在10分鍾後才寫滿當前審計日誌文件，那麼延遲是10分鍾；如果用戶查詢在1個小時之內才寫滿當前審計日誌文件，那麼延遲將是1個小時。
事件流讀取
基於用戶查詢事件流式分析審計日誌的方法，優點也特別明顯：延遲非常小，可以控製在秒級內，實時性表現良好，它解決了XEReader API查詢事件延遲的問題。然而缺點是：也需要依賴SQL Service的啟動狀態，否則會報告異常；在大量查詢瞬間（短時間內）執行的時候（比如用戶不小心寫了一個死循環查詢），重啟SQL Service或者Extend Event Session狀態時，根據我測試的情況來看，這種場景會導致審計日誌記錄丟失，可靠性得不到保證。
最後總結
基於以上三種審計日誌分析方法的優缺點總結來看，我們綜合打分匯總如下：
DMF：對SQL Service有依賴，得分0；延遲取決於Offset的移動效率，得分80；穩定性有保證，得分100；對SQL Server CPU影響較大，得分為0；
XEReader API：對SQL Service無依賴，得分100；延遲取決於查詢產生的速度，得分50；穩定性有保證，得分100；對SQL Server 影響很小，得分為0；
XEReader Stream：對SQL Service有依賴，得分0；延遲非常低，得分100；有不穩定的場景存在，得分50；對SQL Server 影響較小，得分為100；
將綜合打分做成雷達圖，如下：
從這個匯總圖來看，XEReader API直接分析審計日誌文件的方法在依賴性，延遲性，穩定性和影響方麵，綜合表現最佳。
參考文章
Introducing the Extended Events Reader
最後更新：2017-08-21 09:03:11
上一篇：
MySQL · 源碼分析 · SHUTDOWN過程
下一篇： PgSQL · 源碼分析 · PG 優化器中的pathkey與索引在排序時的使用
- 12c create spfile的警示
- Android 4.0設置Dialog點擊屏幕不消失
- 雲棲大會之異構計算，12日，B-3-5不見不散。
- 在Win2003、Win7、XP中配置IIS搭建ASP.NET Web網站或應用程序(1)
- [原創]W2k Driving 學習筆記(二)使用GCC創建 Windows NT 下的內核DLL
- android主題與風格入門
- MySQL · 源碼分析 · mysql認證階段漫遊
- 吐槽Visual Studio 2010
- PostgreSQL 10.0 preview 功能增強 - CLOG oldest XID跟蹤
- 分布式架構--Dubbo服務啟動依賴檢查