背景

在前两篇月报分享中，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版本，我们稍微对实现审计日志功能的扩展事件创建方法稍微修改如下：

  1. USE master
  2. GO
  4. CREATE EVENT SESSION [svrXEvent_User_Define_Testing] ON SERVER 
  5. ADD EVENT sqlserver.sql_statement_completed
  6. ( 
  7.     ACTION 
  8.     ( 
  9.         sqlserver.database_id,
  10.         sqlserver.session_id, 
  11.         sqlserver.username, 
  12.         sqlserver.client_hostname,
  13.         sqlserver.client_app_name,
  14.         sqlserver.sql_text, 
  15.         sqlserver.plan_handle,
  16.         sqlserver.tsql_stack,
  17.         sqlserver.is_system,
  18.         package0.collect_system_time
  19.     ) 
  20.     WHERE sqlserver.username <> N'NT AUTHORITY\SYSTEM'
  21.         AND sqlserver.username <> 'sa'
  22.         AND sqlserver.is_system = 0        
  23. )
  24. ADD TARGET package0.asynchronous_file_target
  25. ( 
  26.     SET 
  27.         FILENAME = N'C:\Temp\svrXEvent_User_Define_Testing.xel', 
  28.         METADATAFILE = N'C:\Temp\svrXEvent_User_Define_Testing.xem',
  29.         MAX_FILE_SIZE = 10,
  30.         MAX_ROLLOVER_FILES = 500
  31. )
  32. WITH (
  33.     EVENT_RETENTION_MODE = NO_EVENT_LOSS,
  34.     MAX_DISPATCH_LATENCY = 5 SECONDS,
  35.     STARTUP_STATE=ON
  36. );
  37. GO
  40. -- We need to enable event session to capture event and event data 
  41. ALTER EVENT SESSION [svrXEvent_User_Define_Testing]
  42. ON SERVER STATE = START;
  43. 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全量读取所有审计日志文件记录的例子：

  1. USE master
  2. GO
  4. SELECT *
  5. FROM sys.fn_xe_file_target_read_file('C:\Temp\svrXEvent_User_Define_Testing*.xel', 
  6.         'C:\Temp\svrXEvent_User_Define_Testing*.xem', null, null)

展示的结果如下： 01.png

从这个结果来看，我们无法明确的知道哪个用户在哪个时间点执行了哪些SQL语句，执行耗时多少等更为详细有价值的信息。这里我们需要采用XML解析的方法来分析Event_data字段中更为丰富的内容。请使用下面的查询语句获取更为详细的信息：

  1. -- This is SQL 2008R2
  2. ;WITH events_cte
  3. AS (
  4.     SELECT
  5.         [event_data] = T.C.query('.'),
  6.         [event_name] = T.C.value('(event/@name)[1]','varchar(100)'),
  7.         [event_time] = DATEADD(mi, DATEDIFF(mi, GETUTCDATE(), CURRENT_TIMESTAMP),T.C.value('(event/@timestamp)[1]','datetime2')),
  8.         [client app name] = T.C.value('(event/action[@name="client_app_name"]/value/text())[1]', 'sysname'),
  9.         [client host name] = T.C.value('(event/action[@name="client_hostname"]/value/text())[1]', 'sysname'),
  10.         [database_id]= T.C.value('(event/action[@name="database_id"]/value/text())[1]', 'int'),
  11.         [cpu time (ms)] = T.C.value('(event/data[@name="cpu"]/value/text())[1]', 'bigint'),
  12.         [logical reads] = T.C.value('(event/data[@name="reads"]/value/text())[1]', 'bigint'),
  13.         [logical writes] = T.C.value('(event/data[@name="writes"]/value/text())[1]', 'bigint'),
  14.         [duration (ms)] = T.C.value('(event/data[@name="duration"]/value/text())[1]', 'bigint'),
  15.         [row count] = T.C.value('(event/data[@name="row_count"]/value/text())[1]', 'bigint'),
  16.         [sql_text] = T.C.value('(event/action[@name="sql_text"]/value/text())[1]','nvarchar(max)'),
  17.         [session_id] = T.C.value('(event/action[@name="session_id"]/value/text())[1]','int'),
  18.         [user_name] = T.C.value('(event/action[@name="username"]/value/text())[1]','sysname'),
  19.         [is_system] = T.C.value('(event/action[@name="is_system"]/value/text())[1]','sysname'),
  20.         [query_timestamp] = T.C.value('(event/action[@name="collect_system_time"]/value/text())[1]','bigint'),
  21.         [query_time] = DATEADD(mi, DATEDIFF(mi, GETUTCDATE(), CURRENT_TIMESTAMP),T.C.value('(event/action[@name="collect_system_time"]/text/text())[1]','datetime2'))
  22.     FROM sys.fn_xe_file_target_read_file('C:\Temp\svrXEvent_User_Define_Testing*.xel', 
  23.         'C:\Temp\svrXEvent_User_Define_Testing*.xem', null, null)
  24.         CROSS APPLY (SELECT CAST(event_data as XML) AS event_data) as T(C)
  25. )
  26. SELECT 
  28.     cte.session_id,
  29.     --cte.query_timestamp,
  30.     --cte.[event_time],
  31.     cte.[query_time],
  32.     --cte.[event_name],
  33.     cte.user_name,
  34.     [database_name] = db.name,
  35.     cte.[database_id],
  36.     cte.[client host name],
  38.     cte.[logical reads],
  39.     cte.[logical writes],
  40.     cte.[cpu time (ms)],
  41.     cte.[duration (ms)],
  42.     --cte.[plan_handle],
  43.     cte.sql_text,
  44.     sql_text_hash = CHECKSUM(cte.sql_text),
  45.     cte.[client app name],
  46.     cte.[event_data],
  47.     cte.is_system
  48. FROM events_cte as cte
  49.     LEFT JOIN sys.databases as db
  50.     on cte.database_id = db.database_id
  51. ORDER BY [query_time] ASC
  52. ;

执行结果展示如下： 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开始读取，执行方法如下：

  1. USE master
  2. GO
  4. SELECT *
  5. FROM sys.fn_xe_file_target_read_file('C:\Temp\svrXEvent_User_Define_Testing*.xel', 
  6.         '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来实现分析审计日志文件。

  1. using System;
  2. using System.Collections.Generic;
  3. using System.Linq;
  4. using System.Text;
  5. using System.Threading.Tasks;
  6. using Microsoft.SqlServer.XEvent.Linq;
  8. namespace MonthlyShareExtendEventDemo
  9. {
  10.     class Program
  11.     {
  12.         static void Main(string[] args)
  13.         {
  14.             string[] xelFiles = new string[] { @"C:\Temp\svrXEvent_User_Define_Testing*.xel" };
  15.             string[] xemFiles = new string[] { @"C:\Temp\svrXEvent_User_Define_Testing*.xem" };
  16.             QueryableXEventData events = new QueryableXEventData(xelFiles, xemFiles);
  17.             foreach (PublishedEvent evt in events)
  18.             {
  19.                 Console.WriteLine("=>>>>>>>>>>>>>>>>>>" + evt.Name);
  21.                 foreach (PublishedEventField fld in evt.Fields)
  22.                 {
  23.                     Console.WriteLine("\tField: {0} = {1}", fld.Name, fld.Value);
  24.                 }
  26.                 foreach (PublishedAction act in evt.Actions)
  27.                 {
  28.                     Console.WriteLine("\tAction: {0} = {1}", act.Name, act.Value);
  29.                 }
  30.                 Console.WriteLine("=<<<<<<<<<<<<<<<" + evt.Name);
  31.             }
  33.             Console.ReadKey();
  35.         }
  36.     }
  37. }

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

注意： 在使用XEReader API分析审计日志，需要依赖两个安装包：SQLSysClrTypes.msi和SharedManagementObjects.msi，请提前安装完毕。

事件流读取

当然我们也可以采用XEReader API事件流的方式读取审计日志，当客户端有查询语句提交到SQL Server 后台服务，事件流会捕获到这个查询行为，并加以分析。事例代码如下：

  1. using System;
  2. using System.Collections.Generic;
  3. using System.Linq;
  4. using System.Text;
  5. using System.Threading.Tasks;
  6. using Microsoft.SqlServer.XEvent.Linq;
  8. namespace XEStreamDemo
  9. {
  10.     class Program
  11.     {
  12.         static void Main(string[] args)
  13.         {
  14.             string connString = string.Format("Data Source=.,{0};Initial Catalog={1};Integrated Security=SSPI", 1433, "master");
  15.             string xeSessionName = @"svrXEvent_User_Define_Testing";
  16.             using (QueryableXEventData eventData = new QueryableXEventData(connString, xeSessionName, EventStreamSourceOptions.EventStream, EventStreamCacheOptions.DoNotCache))
  17.             {
  18.                 foreach (PublishedEvent evt in eventData)
  19.                 {
  20.                     Console.WriteLine("=>>>>>>>>>>>>>>>>>>" + evt.Name);
  22.                     foreach (PublishedEventField fld in evt.Fields)
  23.                     {
  24.                         Console.WriteLine("\tField: {0} = {1}", fld.Name, fld.Value);
  25.                     }
  27.                     foreach (PublishedAction act in evt.Actions)
  28.                     {
  29.                         Console.WriteLine("\tAction: {0} = {1}", act.Name, act.Value);
  30.                     }
  31.                     Console.WriteLine("=<<<<<<<<<<<<<<<" + evt.Name);
  32.                 }
  33.             }
  35.             Console.ReadKey();
  36.         }
  37.     }
  38. }

当执行查询的时候，这个控制台应用程序会捕获到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