For last month's T-SQL Tuesday, I wrote about some undocumented trace flags that help you babysit long-running backup and restore operations. This month, Jes Borland's topic is Extended Events, and I thought I would show new capabilities in SQL Server 2016 that largely make these trace flags obsolete.
If you're playing with CTP2 (you can download it here), you may notice a new category backup_restore and new event backup_restore_progress_trace:
Discovering a new event in CTP2's New Session dialog
Here's a quick and dirty XE session for capturing the data for this event (I've added comments for filtering to only backup or only restore operations; by default, both are included):
CREATE EVENT SESSION [Backup progress] ON SERVER
ADD EVENT sqlserver.backup_restore_progress_trace
(
ACTION(package0.event_sequence)
-- to only capture backup operations:
--WHERE [operation_type] = 0
-- to only capture restore operations:
--WHERE [operation_type] = 1
)
ADD TARGET package0.event_file
(
SET filename = N'C:\temp\BackupProgress.xel'
); -- default options are probably ok
GO
ALTER EVENT SESSION [Backup progress] ON SERVER STATE = START;
GO
Now, let's say I run the following operations – create a database, put a bit of data back it up, drop it, and restore it:
USE [master];
GO
CREATE DATABASE floob;
GO
SELECT s1.* INTO floob.dbo.what
FROM sys.all_objects AS s1
CROSS JOIN sys.all_objects;
GO
BACKUP DATABASE floob TO DISK = 'c:\temp\floob.bak'
WITH INIT, COMPRESSION, STATS = 30;
GO
DROP DATABASE floob;
GO
RESTORE DATABASE floob FROM DISK = 'c:\temp\floob.bak'
WITH REPLACE, RECOVERY;
Now, we can query the data from the event target file:
;WITH x AS
(
SELECT ts,op,db,msg,es
FROM
(
SELECT
ts = x.value(N'(event/@timestamp)[1]', N'datetime2'),
op = x.value(N'(event/data[@name="operation_type"]/text)[1]', N'nvarchar(32)'),
db = x.value(N'(event/data[@name="database_name"])[1]', N'nvarchar(128)'),
msg = x.value(N'(event/data[@name="trace_message"])[1]', N'nvarchar(max)'),
es = x.value(N'(event/action[@name="event_sequence"])[1]', N'int')
FROM
(
SELECT x = CONVERT(XML, event_data)
FROM sys.fn_xe_file_target_read_file
(N'c:\temp\Backup--Progress*.xel', NULL, NULL, NULL)
) AS y
) AS x
WHERE op = N'Backup' -- N'Restore'
AND db = N'floob'
AND ts > CONVERT(DATE, SYSUTCDATETIME())
)
SELECT /* x.db, x.op, x.ts, */
[Message] = x.msg,
Duration = COALESCE(DATEDIFF(MILLISECOND, x.ts,
LEAD(x.ts, 1) OVER(ORDER BY es)),0)
FROM x
ORDER BY es;
For a backup, trace flag 3226 does not suppress any of the output captured by Extended Events. I've left out output columns, due to the filters, for brevity:
| Message | Duration (Milliseconds) |
|---|---|
| BACKUP DATABASE started | 0 |
| Opening the database with S lock | 0 |
| Acquiring bulk-op lock on the database | 0 |
| Synchronizing with other operations on the database is complete | 19 |
| Opening the backup media set | 7 |
| The backup media set is open | 0 |
| Preparing the media set for writing | 0 |
| The media set is ready for backup | 0 |
| Effective options: Checksum=0, Compression=1, Encryption=0, BufferCount=7, MaxTransferSize=1024 KB | 0 |
| Clearing differential bitmaps | 4 |
| Differential bitmaps are cleared | 0 |
| Writing a checkpoint | 6 |
| Checkpoint is complete (elapsed = 6 ms) | 0 |
| Start LSN: 101:111920:43, SERepl LSN: 0:0:0 | 0 |
| Scanning allocation bitmaps | 4 |
| Scanning allocation bitmaps is complete | 0 |
| Calculating expected size of total data | 0 |
| FID=1, ExpectedExtents=10047, IsDifferentialMapAccurate=0 | 0 |
| TotalSize=658440192 bytes | 0 |
| Estimated total size = 658460672 bytes (data size = 658440192 bytes, log size = 20480 bytes) | 0 |
| Work estimation is complete | 0 |
| Last LSN: 101:111960:1 | 0 |
| Writing the leading metadata | 0 |
| BackupStream(0): Writing leading metadata to the device c:\temp\floob.bak | 1 |
| Calculating expected size of total data | 0 |
| FID=1, ExpectedExtents=10047, IsDifferentialMapAccurate=0 | 0 |
| TotalSize=658440192 bytes | 1 |
| Copying data files | 2 |
| Number of data file readers = 1 | 0 |
| Reading the data file D:\SQL Server\MSSQL13.SQL16\DATA\floob.mdf | 0 |
| BackupStream(0): Writing MSDA of size 10048 extents | 391 |
| 30 percent (198180864/658460672 bytes) processed | 554 |
| 60 percent (395313152/658460672 bytes) processed | 576 |
| 90 percent (593494016/658460672 bytes) processed | 184 |
| Completed reading the data file D:\SQL Server\MSSQL13.SQL16\DATA\floob.mdf | 2 |
| BackupStream(0): Padding MSDA with 65536 bytes | 0 |
| BackupStream(0): Total MSDA size = 10048 extents | 0 |
| InitialExpectedSize=658440192 bytes, FinalSize=658440192 bytes, ExcessMode=0 | 0 |
| Last LSN: 101:111960:1 | 0 |
| Copying data files is complete | 0 |
| Copying transaction log | 0 |
| MediaFamily(0): FID=2, VLFID=101, DataStreamSize=65536 bytes | 4 |
| Copying transaction log is complete | 0 |
| Writing the trailing metadata | 0 |
| BackupStream(0): Writing trailing metadata to the device c:\temp\floob.bak | 0 |
| Writing the end of backup set | 30 |
| Writing history records | 12 |
| Writing history records is complete (elapsed = 11 ms) | 0 |
| BACKUP DATABASE finished | 0 |
Event data for a backup operation
For a restore, you will see these rows:
| Message | Duration (Milliseconds) |
|---|---|
| RESTORE DATABASE started | 0 |
| Opening the backup set | 3 |
| Processing the leading metadata | 0 |
| Planning begins | 23 |
| Effective options: Checksum=0, Compression=1, Encryption=0, BufferCount=6, MaxTransferSize=1024 KB | 0 |
| Planning is complete | 0 |
| Beginning OFFLINE restore | 0 |
| Attached database as DB_ID=5 | 1 |
| Preparing containers | 534 |
| Containers are ready | 1097 |
| Restoring the backup set | 0 |
| Estimated total size to transfer = 658460672 bytes | 0 |
| Transferring data | 1 |
| BackupStream(0): Processing MSDA of size 10048 extents | 3282 |
| BackupStream(0): Completed MSDA | 0 |
| Waiting for log zeroing to complete | 3 |
| Log zeroing is complete | 0 |
| BackupStream(0): Processing MSTL (FID=2, VLFID=101, size=65536 bytes) | 1024 |
| Data transfer is complete | 14 |
| Backup set is restored | 45 |
| Offline roll-forward begins | 1 |
| Processing 68 VLF headers | 69 |
| Processing VLF headers is complete | 11 |
| First LSN: 101:111920:43, Last LSN: 101:111960:1 | 0 |
| Stop LSN: 101:111960:1 | 4 |
| Offline roll-forward is complete | 17 |
| Database fixup is complete | 2 |
| Transitioning database to ONLINE | 2 |
| Restarting database for ONLINE | 87 |
| PostRestoreContainerFixups begins | 5 |
| PostRestoreContainerFixups is complete | 2 |
| PostRestoreReplicationFixup begins | 107 |
| PostRestoreReplicationFixup is complete | 2 |
| Database is restarted | 9 |
| Resuming any halted Fulltext crawls | 6 |
| Writing history records | 13 |
| Writing history records is complete (elapsed = 13 ms) | 2 |
| MSDB maintenance is complete | 2 |
| RESTORE DATABASE finished | 0 |
Event data for a restore operation
If you're troubleshooting a slow backup or restore operation, you could easily filter on the duration, so that you only see events that took longer than n milliseconds, for example. The only thing I don't see in this output is any way to tell if instant file initialization was in effect during the restore – you still may need trace flag 3004, as described in my post for last month's T-SQL Tuesday.
Don't forget to stop the session (but feel free to keep the session definition on the server, so you can use it again):
ALTER EVENT SESSION [Backup progress] ON SERVER STATE = STOP;
I did not perform any performance tests or impact analysis, but in general, I would say that – like the trace flags – this isn't something you'd want running all the time, but only when troubleshooting a specific operation. It's a bit easier to set up this session and query the data, IMHO, than to turn on the trace flags and parse all of the output from SQL Server's error log.
