借助扩展事件查看SQL 2016备份和还原操作的内幕

当遇到备份或者还原操作占用较长时间时，很多人会问：

备份/还原是不是僵死了？要不要kill掉，再重来？
到底是哪一个部分的操作占用较长时间？
到底现在进行到什么阶段了？

在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详细情况：

借助扩展事件查看SQL 2016备份和还原操作的内幕

由这些信息，我们能够知道此备份操作主要的步骤有哪些，哪些步骤最耗时间。

还原

还原我用的是上一个备份生成的文件,并且使用了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;

借助扩展事件查看SQL 2016备份和还原操作的内幕

通过以上信息，我们能够知道还原数据库时的主要操有哪些，哪些步骤比较耗时。

现实情况中数据库还原，roll-forward之后应该还有一个undo(roll-back)操作来撤消未提交事务的修改。

总结

虽然是SQL 2016才引入这个新的XE事件，但是在其它版本上，理论是相通的，只是一些细节的差别。
本文使用的是一个小的示例库，现实中生产库的情况要复杂一些。
XE是一大利器，可以帮我们验证很多理论细节。

秒客网

借助扩展事件查看SQL 2016备份和还原操作的内幕

备份

还原

总结

相关文章