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直接分析审计日志文件的方法在依赖性，延迟性，稳定性和影响方面，综合表现最佳。

MSSQL· 实现分析 · Extend Event日志文件的分析方法

热门文章

最新文章

相关课程

相关电子书

相关实验场景