Aaron Bertrand

T-SQL Tuesday #67 : New Backup and Restore Extended Events

SentryOne eBooks

In these books, you will find useful, hand-picked articles that will help give insight into some of your most vexing performance problems. These articles were written by several of the SQL Server industry’s leading experts, including Paul White, Paul Randal, Jonathan Kehayias, Erin Stellato, Glenn Berry, Aaron Bertrand, and Joe Sack.

Free Download

Featured Author

Paul Randal, CEO of SQLskills, writes about knee-jerk performance tuning, DBCC, and SQL Server internals.

Paul’s Posts

T-SQL Tuesday #67

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:

New event discovered in SQL Server 2016 Extended EventsDiscovering 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.