背景

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

  • Extend Event是否满足可靠性要求

  • Extend Event是否满足吞吐量要求

  • Extend Event对SQL Server本身语句查询性能影响到底有多大

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

测试环境介绍

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

环境配置

主机： 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。语句如下：

  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.database_name,
  11.         sqlserver.session_id, 
  12.         sqlserver.username, 
  13.         sqlserver.client_hostname,
  14.         sqlserver.client_app_name,
  15.         sqlserver.sql_text, 
  16.         sqlserver.query_hash,
  17.         sqlserver.query_plan_hash,
  18.         sqlserver.plan_handle,
  19.         sqlserver.tsql_stack,
  20.         sqlserver.is_system,
  21.         package0.collect_system_time
  22.     ) 
  23.     WHERE sqlserver.username <> N'NT AUTHORITY\SYSTEM'
  24.         AND sqlserver.username <> 'sa'
  25.         AND (NOT sqlserver.like_i_sql_unicode_string(sqlserver.client_app_name, '%IntelliSense'))
  26.         AND sqlserver.is_system = 0
  28. )
  29. ADD TARGET package0.asynchronous_file_target
  30. ( 
  31.     SET 
  32.         FILENAME = N'C:\Temp\svrXEvent_User_Define_Testing.xel', 
  33.         MAX_FILE_SIZE = 10,
  34.         MAX_ROLLOVER_FILES = 500
  35. )
  36. WITH (
  37.     EVENT_RETENTION_MODE = NO_EVENT_LOSS,
  38.     MAX_DISPATCH_LATENCY = 5 SECONDS
  39. );
  40. GO

启用Extended Event Session

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

  1. USE master
  2. GO
  4. -- We need to enable event session to capture event and event data 
  5. ALTER EVENT SESSION [svrXEvent_User_Define_Testing]
  6. ON SERVER STATE = START;
  7. 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

  • 平均每秒抓取5316条审计日志和记录5.43MB日志文件

  • 平均每分钟抓取318963条审计日志和记录325.6MB日志文件

  • 平均每小时抓取19137822条审计日志和记录19.08GB日志文件

  • 平均每天抓取459307728条审计日志和记录457.92GB日志文件

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

对SQL Server性能影响

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

定性分析

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

  • 单位时间内迭代千查询的次数越多，性能越优

  • 千查询消耗时间越少，性能越优

  • 停止和启用Extend Event Session情况下，以上两个指标越接近，差异越小，说明Extend Event对SQL Server性能影响越小，因此也就越好

测试方法

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

  1. --Create database sqlworkshops
  2. use master
  3. if (db_id('sqlworkshops') is NULL)
  4. begin
  5.     create database sqlworkshops
  6.     alter database sqlworkshops set recovery simple
  7. end
  8. go
  9. --Create table tab72
  10. use sqlworkshops
  11. if (object_id('tab72') is not NULL)
  12.     drop table tab72
  13. go
  14. use sqlworkshops
  15. create table tab72 (c1 int primary key clustered, c2 int, c3 nchar(2000))
  16. 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
  17. update tab72 set c3 = 'Advanced SQL Server Performance Monitoring & Tuning Hands-on Workshop from SQLWorkshops.com' where c1 = 10000
  18. update statistics tab72 with fullscan
  19. checkpoint
  20. go

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

  1. use sqlworkshops
  2. set nocount on
  3. declare @i int
  4. set @i = 1
  5. while @i <= 1000
  6. begin
  7.     select * from tab72 where c3 like '%SQLWorkshops%' and c1 between 1 and 10
  8.         option (maxdop 1)
  9.     set @i = @i + 1
  10. end
  11. go

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

千查询平均耗时

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

  • AT_PK_XE：启用Extend Event Session场景下，使用主键千查询的平均耗时。

  • AT_PK_nonXE：停用Extend Event Session场景下，使用主键千查询的平均耗时。

  • AT_PK_Range_XE：启用Extend Event Session场景下，使用主键范围查找，千查询的平均耗时。

  • AT_PK_Range_nonXE：停用Extend Event Session场景下，使用主键范围查找，千查询的平均耗时。

  • AT_nonXE_XE_Gap：使用主键千查询，在启用和停用Extend Event Session两种场景的平均耗时差异。

  • AT_Range_nonXE_XE_Gap：使用主键范围千查询，在启用和停用Extend Event Session两种场景的平均耗时差异。

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

单主键千查询

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

  • 线条AT_nonXE_XE_Gap表示停止和启用Extend Event Session两个场景，千查询平均时间消耗差异，总体差异不大；但差异会随着线程数量的不断增加，而拉大。

  • 在并发线程为4的时候（这个数字和我的测试机CPU Cores个数惊人的相等），千查询平均时间消耗差异最小，仅为29毫秒，千查询平均耗时影响为29*100/270 = 10.74%，即单语句查询的平均耗时影响为0.01074%。

主键范围千查询

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

  • 线条AT_Range_nonXE_XE_Gap表示停止和启用Extend Event Session两个场景，千查询平均时间消耗差异，总体差异不大（除开2个线程情况下）；但差异会随着线程数量的不断增加，而拉大。

  • 同样，在并发线程为4的时候，千查询平均时间消耗差异最小，仅为58毫秒，千查询平均耗时影响为58*100/1712=3.39%，即单语句查询平均耗时影响为0.00339%。

平均耗时总结

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

千查询迭代次数

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

单主键千查询

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

  • AI_nonXE_XE_Gap线条表示千查询迭代次数差异，随着并发线程数增加，差异被拉大。

  • 禁用和启用Extend Event Session场景下，当并发线程数为4的时候，千查询迭代次数差异最小，这个规律和单主键千查询平均时间消耗规律相似。启用Extend Event Session，对迭代次数影响是85*100/897=9.47%，换算成单个查询语句的迭代次数影响为0.00947%。

主键范围千查询

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

  • 迭代次数随着线程数量的增加而增加，在16个并发线程时达到顶峰，迭代次数开始下降。

  • 禁用和启用Extend Event Session场景下，千查询迭代次数差异在并发4个线程时（忽略并发线程为2的情况），最小值为8，这个规律和千查询平均时间消耗规律十分类似。启动Extend Event Session后，对千查询的迭代次数影响为8*100/142=5.63%，换算成单个查询语句的迭代次数影响为0.00563%。

千查询迭代次数总结

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

性能影响总结

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

  • 单主键查找千查询，平均耗时影响为10.74%；换算为单主键单语句查询，性能影响为0.01074%。

  • 单主键查找千查询，单位时间内（1分钟）迭代次数影响（吞吐量）为9.47%；换算为单主键单语句查询，性能影响为0.00947%。

  • 主键范围查找千查询，平均耗时影响为3.39%；换算成单主键单语句查询，性能影响为0.00339%。

  • 主键范围查找千查询，单位时间内（1分钟）迭代次数影响（吞吐量）为5.63%；换算成单主键单语句查询，性能影响为0.00563%。

将以上文字描述的数字解决做成一个直观的图形，我们发现在开启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测试方法参考链接