藉助擴展事件查看SQL 2016備份和還原操作的內幕

當遇到備份或者還原操作占用較長時間時，很多人會問：

1. 備份/還原是不是僵死了？要不要kill掉，再重來？
2. 到底是哪一個部分的操作占用較長時間？
3. 到底現在進行到什麼階段了？

在SQL 2016 之前，要回答這些問題會比較困難一些，或者藉助某些不受支持的方式。SQL 2016開始引入了新擴展事件 backup_restore_progress_trace 來跟蹤備份和還原操作。我們可以使用它們來觀察備份和還原的更詳細的信息。

備份

先創建一個XE Session觀察備份：

CREATE EVENT SESSION [xe_backup] ON SERVER 
ADD EVENT sqlserver.backup_restore_progress_trace(
    ACTION(
        sqlos.task_time,sqlserver.database_id,sqlserver.database_name,
        sqlserver.nt_username,sqlserver.session_id,sqlserver.session_nt_username,
        sqlserver.sql_text,sqlserver.username
    )
    )
ADD TARGET package0.event_file(SET filename=N'C:\Joe\xe\xeBackup.xel')
WITH (STARTUP_STATE=ON)
GO
ALTER EVENT SESSION [xe_backup] ON SERVER 
STATE=START;
GO

完成備份後，再來分析我們捕獲的信息：

BACKUP DATABASE [AdventureWorks2016CTP3] TO  DISK = N'C:\SQL2016\MSSQL13.MSSQLSERVER\MSSQL\Backup\aw.bak' 
WITH NOFORMAT, INIT,  NAME = N'AdventureWorks2016CTP3-Full Database Backup', 
SKIP, NOREWIND, NOUNLOAD, COMPRESSION,  STATS = 10
GO
ALTER EVENT SESSION [xe_backup] ON SERVER 
STATE=STOP;
GO
;WITH xevent AS (  
SELECT timestamp,operation_type,database_name,trace_level,trace_message,event_sequence  
FROM   (   
SELECT     timestamp  = xevent.value(N'(event/@timestamp)[1]', N'datetime2'),    
operation_type  = xevent.value(N'(event/data[@name="operation_type"]/text)[1]', N'nvarchar(32)'),    
database_name  = xevent.value(N'(event/data[@name="database_name"])[1]', N'nvarchar(128)'),    
trace_message = xevent.value(N'(event/data[@name="trace_message"])[1]', N'nvarchar(max)'),    
trace_level = xevent.value(N'(event/data[@name="trace_level"])[1]', N'nvarchar(max)'), 
event_sequence  = xevent.value(N'(event/action[@name="event_sequence"])[1]', N'int')   
FROM    (    SELECT xevent = CONVERT(XML, event_data)      
             FROM sys.fn_xe_file_target_read_file(N'c:\joe\xe\xeBackup_*.xel', NULL, NULL, NULL)   )
         AS y  
    ) AS xevent )

SELECT   database_name,timestamp,trace_level,trace_message,   
Duration = COALESCE( DATEDIFF(MILLISECOND, xevent.timestamp,LEAD(xevent.timestamp, 1) OVER(ORDER BY event_sequence)),0)
FROM xevent
ORDER BY event_sequence;

我這裡的查詢結果總共56行，highlight部分主要操作的信息。Duration列表示此操作所有時間。

由結果可以看到備份的trace_level分為Information of major steps in the operation和Verbose I/O related information，前者表示備份操作的中的主要步驟，後者表示某個步驟IO詳細情況：

由這些信息，我們能夠知道此備份操作主要的步驟有哪些，哪些步驟最耗時間。

還原

還原我用的是上一個備份生成的文件,並且使用了REPLACE。

CREATE EVENT SESSION [xe_restore] ON SERVER 
ADD EVENT sqlserver.backup_restore_progress_trace(
    ACTION(package0.event_sequence,sqlos.task_time,sqlserver.database_id,sqlserver.database_name,
    sqlserver.nt_username,sqlserver.server_instance_name,sqlserver.session_id,sqlserver.sql_text))
ADD TARGET package0.event_file(SET filename=N'C:\Joe\xe\xeRestore.xel')
WITH (STARTUP_STATE=ON)
GO

ALTER EVENT SESSION [xe_restore] ON SERVER 
STATE=START
GO
USE [master]
RESTORE DATABASE [AdventureWorks2016CTP3] FROM  DISK = N'C:\SQL2016\MSSQL13.MSSQLSERVER\MSSQL\Backup\aw.bak' 
WITH  FILE = 1,  NOUNLOAD, REPLACE,  STATS = 5
GO

觀察XE的數據：

ALTER EVENT SESSION [xe_restore] ON SERVER 
STATE=STOP
GO
;WITH xevent AS (  
SELECT timestamp,operation_type,database_name,trace_level,trace_message,event_sequence  
FROM   (   
SELECT     timestamp  = xevent.value(N'(event/@timestamp)[1]', N'datetime2'),    
operation_type  = xevent.value(N'(event/data[@name="operation_type"]/text)[1]', N'nvarchar(32)'),    
database_name  = xevent.value(N'(event/data[@name="database_name"])[1]', N'nvarchar(128)'),    
trace_message = xevent.value(N'(event/data[@name="trace_message"])[1]', N'nvarchar(max)'),    
trace_level = xevent.value(N'(event/data[@name="trace_level"])[1]', N'nvarchar(max)'), 
event_sequence  = xevent.value(N'(event/action[@name="event_sequence"])[1]', N'int')   
FROM    (    SELECT xevent = CONVERT(XML, event_data)      
             FROM sys.fn_xe_file_target_read_file(N'c:\joe\xe\xeRestore_*.xel', NULL, NULL, NULL)   )
         AS y  
    ) AS xevent )

SELECT   database_name,timestamp,trace_level,trace_message,   
Duration = COALESCE( DATEDIFF(MILLISECOND, xevent.timestamp,LEAD(xevent.timestamp, 1) OVER(ORDER BY event_sequence)),0)
FROM xevent
ORDER BY event_sequence;

通過以上信息，我們能夠知道還原資料庫時的主要操有哪些，哪些步驟比較耗時。

現實情況中資料庫還原，roll-forward之後應該還有一個undo(roll-back)操作來撤消未提交事務的修改。

總結

1. 雖然是SQL 2016才引入這個新的XE事件，但是在其它版本上，理論是相通的，只是一些細節的差別。
2. 本文使用的是一個小的示例庫，現實中生產庫的情況要複雜一些。
3. XE是一大利器，可以幫我們驗證很多理論細節。