数据库内核月报 - 2017 / 08

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)

展示的结果如下:
01.png

从这个结果来看,我们无法明确的知道哪个用户在哪个时间点执行了哪些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
;

执行结果展示如下:
02.png

从这个结果集中,我们可以很清楚的知道每一条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)

执行结果截图如下:
03.png

当然,你也可以使用“全量读取”中的分析方法来获取部分读取到的审计日志详细信息,在此不再累述。

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();

        }
    }
}

我截图其中一条得到的审计日志如下图所示:
04.png

注意:
在使用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 服务端执行的查询语句,如下截图:
05.png

注意:
基于事件流分析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’.
异常信息截图如下:
06.png

三种方法对比

这一章节介绍三种审计日志分析方法的对比,我们将会从以下几个角度来衡量这三种方法:

是否依赖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开销。如下截图所示:
07.png

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;

08.png

将综合打分做成雷达图,如下:
09.png

从这个汇总图来看,XEReader API直接分析审计日志文件的方法在依赖性,延迟性,稳定性和影响方面,综合表现最佳。

参考文章

Introducing the Extended Events Reader