Aaron Bertrand

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

Free eBook : Query Optimization with SentryOne Plan Explorer
SentryOne Newsletters

The SQLPerformance.com bi-weekly newsletter keeps you up to speed on the most recent blog posts and forum discussions in the SQL Server community.

eNews is a bi-monthly newsletter with fun information about SentryOne, tips to help improve your productivity, and much more.

Subscribe

Featured Author

Itzik is a T-SQL trainer, a co-founder of SolidQ, and blogs about T-SQL fundamentails and query tuning.

Itzik’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.