MSSQL · 實現分析 · Extend Event實現審計日誌對SQL Server性能影響

背景

在上一篇月報分享中，我們介紹了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)均采用默認值。

測試環境詳情截圖如下：

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多萬條記錄，參見如下截圖：

而，Extend Event總共生成了341個審計日誌文件，每個日誌文件最大大小為10MB（這裏調整了最多的文件數量為500，以滿足測試產生的數據要求），總共大小為近3.18GB。

使用係統提供的函數sys.fn_xe_file_target_read_file讀取Extend Event生成的審計日文件記錄總數，展示也是3189637條，這個記錄總數和SQL Profiler抓取到的記錄數是恰好吻合。

從測試的結果來看，Extend Event實現審計日誌功能可靠性有保證，在10分鍾310多萬條語句執行的壓力下，依然可以工作良好。

吞吐量

可靠性測試是保證Extend Event在抓取審計日誌時的穩定性和功能健壯性，簡單講就是“不丟數據”，而吞吐量的測試是要回答“Extend Event到底在多大的查詢吞吐量時，依然能夠工作良好？”。就可靠性測試的我們來簡單推算一下：10分鍾的測試，共執行3189637條查詢，生成了3.18GB的審計日誌文件，以此來推算每秒，每分鍾，每小時，每天可以抓取到的查詢記錄數和產生的日誌文件大小，如下圖計算所示：

平均每秒抓取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萬條數據。

--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，在開啟不同數量的並發查詢線程情況下，獲取到的千查詢平均時間消耗數據統計如下：
千查詢平均耗時統計數據表格

其中：

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圖，我直觀的來看看平均時間消耗差異。

單主鍵千查詢

使用單主鍵查找的千查詢平均時間消耗圖

從這個圖，我們可以做如下總結：

線條AT_nonXE_XE_Gap表示停止和啟用Extend Event Session兩個場景，千查詢平均時間消耗差異，總體差異不大；但差異會隨著線程數量的不斷增加，而拉大。
在並發線程為4的時候（這個數字和我的測試機CPU Cores個數驚人的相等），千查詢平均時間消耗差異最小，僅為29毫秒，千查詢平均耗時影響為29*100/270 = 10.74%，即單語句查詢的平均耗時影響為0.01074%。

主鍵範圍千查詢

使用主鍵範圍查找的千查詢平均時間消耗圖

從這個圖，我們可以做如下總結：

線條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分鍾內）千查詢迭代次數。千查詢迭代次數統計表格

其中，表格每行數據表示千查詢迭代次數，第一列與千查詢平均時間消耗表達含義類似，這裏不再累述。

單主鍵千查詢

使用單主鍵千查詢在單位時間內的迭代次數統計數據，做圖如下：

從圖表直觀反映，我們可以發現如下規律：

AI_nonXE_XE_Gap線條表示千查詢迭代次數差異，隨著並發線程數增加，差異被拉大。
禁用和啟用Extend Event Session場景下，當並發線程數為4的時候，千查詢迭代次數差異最小，這個規律和單主鍵千查詢平均時間消耗規律相似。啟用Extend Event Session，對迭代次數影響是85*100/897=9.47%，換算成單個查詢語句的迭代次數影響為0.00947%。

主鍵範圍千查詢

使用主鍵範圍查找的千查詢迭代次數做圖如下：

同樣，我們可以直觀的發現以下規律：

迭代次數隨著線程數量的增加而增加，在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%。

從這個量化分析的總結來看，Extend Event對用戶SQL Server性能影響是，千查詢語句的性能影響在3% ~ 10%之間；單條語句查詢性能和吞吐量損失均在0.01%小幅波動，這個影響相對於Profiler已經非常小了。因此，方案可行，並且影響在可控的範圍內。

參考文章

最後更新：2017-07-21 09:03:04

MSSQL · 實現分析 · Extend Event實現審計日誌對SQL Server性能影響

背景

測試環境介紹

環境配置

Extend Event Session對象創建

啟用Extended Event Session

可靠性和吞吐量測試

可靠性

吞吐量

對SQL Server性能影響

定性分析

測試方法

千查詢平均耗時

單主鍵千查詢

主鍵範圍千查詢

平均耗時總結

千查詢迭代次數

單主鍵千查詢

主鍵範圍千查詢

千查詢迭代次數總結

性能影響總結

參考文章

上一篇： MySQL · myrocks · myrocks寫入分析

下一篇： TokuDB · 引擎特性 · HybridDB for MySQL高壓縮引擎TokuDB 揭秘

相關內容

熱門內容

最新內容