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