数据库内核月报

数据库内核月报 － 2017 / 07

MSSQL · 实现分析 · Extend Event实现审计日志对SQL Server性能影响

Author: 风移

背景

在上一篇月报分享中，我们介绍了SQL Server实现审计日志功能的四种方法，最终的结论是使用Extend Event(中文叫扩展事件)实现审计日志方法是最优选择，详情参见MSSQL · 实现分析 · SQL Server实现审计日志的方案探索。那么，使用Extend Event实现审计日志的方案会面对如下疑问：

这篇文章就是围绕这几个问题的量化分析来展开的。

测试环境介绍

首先，需要说明一下测试环境，我的所有测试数据量化结果都是基于我的测试环境的而得出来的。如果用户测试环境的配置不同，可能会得到不同的测试量化数据。我的测试环境介绍如下。

环境配置

主机： Mac OS X 10.11.6系统上VM主机 CPU：i7-4770 2.2GHz 4 Cores 4 Logical Processor Memory: 5GB Storage: SSD SQL Server：SQL Server 2008R2 测试工具：SQLTest 1.0.45.0 SQL Server几个关键的配置：max degree of parallelism和max server memory (MB)均采用默认值。

测试环境详情截图如下： 01.png

Extend Event Session对象创建

使用Create Event Session On Server语句创建基于实例级别的Extended Event。语句如下：

USE master
GO

CREATE EVENT SESSION [svrXEvent_User_Define_Testing] ON SERVER 
ADD EVENT sqlserver.sql_statement_completed
( 
	ACTION 
	( 
		sqlserver.database_id,
		sqlserver.database_name,
		sqlserver.session_id, 
		sqlserver.username, 
		sqlserver.client_hostname,
		sqlserver.client_app_name,
		sqlserver.sql_text, 
		sqlserver.query_hash,
		sqlserver.query_plan_hash,
		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 (NOT sqlserver.like_i_sql_unicode_string(sqlserver.client_app_name, '%IntelliSense'))
		AND sqlserver.is_system = 0
		
)
ADD TARGET package0.asynchronous_file_target
( 
	SET 
		FILENAME = N'C:\Temp\svrXEvent_User_Define_Testing.xel', 
		MAX_FILE_SIZE = 10,
		MAX_ROLLOVER_FILES = 500
)
WITH (
	EVENT_RETENTION_MODE = NO_EVENT_LOSS,
	MAX_DISPATCH_LATENCY = 5 SECONDS
);
GO

启用Extended Event Session

Extended Event Session对象创建完毕后，需要启动这个session对象，方法如下：

USE master
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

可靠性和吞吐量测试

在选择使用Extend Event实现审计日志功能的解决方案之前，该技术方案可行性和吞吐量直接关系到产品的稳定性和功能延续性，这些特性对于审计日志功能都非常重要，我们需要经过严格的可靠性和吞吐量测试，以确保Extend Event技术方案满足这两方面的要求的同时，又不会对SQL Server本身性能和吞吐量造成大的影响（假设条语句性能和吞吐量影响超过5%定义为大的影响）。

可靠性

可靠性测试的方法是，我们使用SQLTest工具开4个并发线程执行查询语句，持续运行10分钟时间，同时，使用Profiler抓取SQL:stmtCompleted事件(功能和Extend Event事件sql_statement_completed功能相同)，来校验Extend Event抓取的记录数，如果两者的记录数相同说明Extend Event满足可靠性要求。在测试的短短10分钟左右时间内，查看Profiler抓取到的记录数为3189637，总共310多万条记录，参见如下截图： 02.png 而，Extend Event总共生成了341个审计日志文件，每个日志文件最大大小为10MB（这里调整了最多的文件数量为500，以满足测试产生的数据要求），总共大小为近3.18GB。 03.png 使用系统提供的函数sys.fn_xe_file_target_read_file读取Extend Event生成的审计日文件记录总数，展示也是3189637条，这个记录总数和SQL Profiler抓取到的记录数是恰好吻合。 04.png 从测试的结果来看，Extend Event实现审计日志功能可靠性有保证，在10分钟310多万条语句执行的压力下，依然可以工作良好。

吞吐量

可靠性测试是保证Extend Event在抓取审计日志时的稳定性和功能健壮性，简单讲就是“不丢数据”，而吞吐量的测试是要回答“Extend Event到底在多大的查询吞吐量时，依然能够工作良好？”。就可靠性测试的我们来简单推算一下：10分钟的测试，共执行3189637条查询，生成了3.18GB的审计日志文件，以此来推算每秒，每分钟，每小时，每天可以抓取到的查询记录数和产生的日志文件大小，如下图计算所示： 05.png

从这个数量级别来看，Extend Event实现审计日志功能平均每天吞吐量可以达到4亿5千万条审计日志记录；生成457.92GB审计日志文件，完全可以满足我们的业务要求吞吐量了。

对SQL Server性能影响

为了测试Extend Event对用户SQL Server实例的性能影响，我们的思路是在停止和启用Extend Event Session的场景下，统计一千条相同查询（简称千查询）在不同数量并发线程情况下时间消耗和单位时间内（以1分钟为单位）的迭代次数，最终以得到的测试数据做为标准。

定性分析

测试之前，对测试数据的定性分析逻辑是：

测试方法

建立测试对象表：创建测试表tab72，并初始化5万条数据。

--Create database sqlworkshops
use master
if (db_id('sqlworkshops') is NULL)
begin
	create database sqlworkshops
	alter database sqlworkshops set recovery simple
end
go
--Create table tab72
use sqlworkshops
if (object_id('tab72') is not NULL)
	drop table tab72
go
use sqlworkshops
create table tab72 (c1 int primary key clustered, c2 int, c3 nchar(2000))
insert into tab72 with (tablock) select c1 as c1, c1 as c2, replicate('a', 2000) as c3 from (select top (50000) row_number() over(order by t1.column_id) as c1 from sys.all_columns t1 cross apply sys.all_columns t2) as t order by c1
update tab72 set c3 = 'Advanced SQL Server Performance Monitoring & Tuning Hands-on Workshop from SQLWorkshops.com' where c1 = 10000
update statistics tab72 with fullscan
checkpoint
go

千查询测试语句：就是针对某个查询语句循环1000次。

use sqlworkshops
set nocount on
declare @i int
set @i = 1
while @i <= 1000
begin
	select * from tab72 where c3 like '%SQLWorkshops%' and c1 between 1 and 10
		option (maxdop 1)
	set @i = @i + 1
end
go

测试方法：使用SQLTest，分别测试在1、2、4、8、16、32个并发线程情况下，单位时间内（1分钟）千查询的平均迭代次数和时间消耗。

千查询平均耗时

使用SQLTest，在开启不同数量的并发查询线程情况下，获取到的千查询平均时间消耗数据统计如下： 千查询平均耗时统计数据表格 06_tb1.png 其中：

将“千查询平均耗时统计数据表格”数据，做成EChart图，我直观的来看看平均时间消耗差异。

单主键千查询

使用单主键查找的千查询平均时间消耗图 07.png 从这个图，我们可以做如下总结：

主键范围千查询

使用主键范围查找的千查询平均时间消耗图 08.png 从这个图，我们可以做如下总结：

平均耗时总结

根据以上对千查询平均耗时统计数据和做图，总结如下： 无论是基于主键的单值查询语句，还是主键的范围查询语句，禁用和启用Extend Event Session，对于千查询的平均耗时差异不大，在并发线程为4的时候，差异最小；千查询平均耗时差异为29毫秒和58毫秒，性能影响为10.74%和3.39%；单语句查询平均耗影响分别为0.01074%和0.00339%。

千查询迭代次数

这一小节从另外一个角度来看Extend Event对SQL Server性能的影响，让我们来看看在单位时间内（1分钟内）千查询迭代次数。千查询迭代次数统计表格 09_tb2.png 其中，表格每行数据表示千查询迭代次数，第一列与千查询平均时间消耗表达含义类似，这里不再累述。

单主键千查询

使用单主键千查询在单位时间内的迭代次数统计数据，做图如下： 10.png 从图表直观反映，我们可以发现如下规律：

主键范围千查询

使用主键范围查找的千查询迭代次数做图如下： 11.png 同样，我们可以直观的发现以下规律：

千查询迭代次数总结

根据以上对千查询迭代次数数据和做图，总结如下： 无论是基于主键的单值查询语句，还是主键的范围查询语句，禁用和启用Extend Event Session，千查询的迭代次数差异并不大，在并发线程为4的时候，差异达到最小值；千查询迭代次数差异为85和8次，启用Extend Event Session后，对千查询在主键查找和主键范围查找场景下，迭代次数影响为9.47%和5.63%；单查询平均迭代次数影响分别为0.00947%和0.00563%。

性能影响总结

在启用了Extend Event Session抓取审计日志以后，对用户SQL Server实例性能影响的量化分析总结如下：

将以上文字描述的数字解决做成一个直观的图形，我们发现在开启Extend Event实现审计日志功能时，对于单条语句查询性能的影响最大约为0.01%；而对于单语句查询吞吐量的影响不超过0.01%。 12.png 从这个量化分析的总结来看，Extend Event对用户SQL Server性能影响是，千查询语句的性能影响在3% ~ 10%之间；单条语句查询性能和吞吐量损失均在0.01%小幅波动，这个影响相对于Profiler已经非常小了。因此，方案可行，并且影响在可控的范围内。

参考文章

  1. Measuring “Observer Overhead” of SQL Trace vs. Extended Events

  2. SQLTest测试方法参考链接