How to capture SQL Server database RESTORE details with Extended Events

01 July,2021 by Tom Collins

If you want to troubleshoot a slow SQL Server Restore or just find out more about all the restore steps , use these techniques to give you an insight 

 

Code to create the Event Session, Add Event - note : the filter for restore operation type & start the Event Session

CREATE EVENT SESSION [backupRestoreTrace] ON SERVER 
ADD EVENT sqlserver.backup_restore_progress_trace
   (WHERE [operation_type] = 1 )   
ADD TARGET package0.event_file(SET filename=N'backupRestoreTrace')
WITH (STARTUP_STATE=OFF)
GO
ALTER EVENT SESSION [backupRestoreTrace]  
ON SERVER  
STATE = start;  
GO  

Code to read the output of the Event Session. 

 

;WITH xevent_backupRestoreTrace AS 
(
  SELECT ts,op_type,dbase_name,message,event_seq
  FROM 
  (
   SELECT 
    ts  = xevent_backupRestoreTrace.value(N'(event/@timestamp)[1]', N'datetime2'),
    op_type  = xevent_backupRestoreTrace.value(N'(event/data[@name="operation_type"]/text)[1]', N'nvarchar(32)'),
    dbase_name  = xevent_backupRestoreTrace.value(N'(event/data[@name="database_name"])[1]', N'nvarchar(128)'),
    message = xevent_backupRestoreTrace.value(N'(event/data[@name="trace_message"])[1]', N'nvarchar(max)'),
    event_seq  = xevent_backupRestoreTrace.value(N'(event/action[@name="event_sequence"])[1]', N'int')
   FROM 
   (
    SELECT xevent_backupRestoreTrace = CONVERT(XML, event_data) 
     FROM sys.fn_xe_file_target_read_file
          (N'backupRestoreTrace_*.xel', NULL, NULL, NULL)
   ) AS y
  ) AS xevent_backupRestoreTrace

 
)
SELECT 
  [Message] = xevent_backupRestoreTrace.message, 
  Duration = COALESCE(DATEDIFF(MILLISECOND, xevent_backupRestoreTrace.ts, 
             LEAD(xevent_backupRestoreTrace.ts, 1) OVER(ORDER BY event_seq)),0)
FROM xevent_backupRestoreTrace
ORDER BY event_seq;

Sample output from a Restore overwriting an existing database

Message | Duration
Acquiring U lock on the database 0
RESTORE DATABASE started 1
Acquiring bulk-op lock on the database 2
Opening the backup set 1467
Processing the leading metadata 6
Planning begins 29
Halting Fulltext crawls 11
Acquired X lock on the database 0
Acquiring X lock on the database 0
Effective options: Checksum=0, Compression=0, Encryption=0, BufferCount=20, MaxTransferSize=2048 KB 0
Planning is complete 2
Beginning OFFLINE restore 182
Preparing containers 28
Containers are ready 7
Estimated total size to transfer = 5906944 bytes 0
Restoring the backup set 0
Transferring data 5
FileHandleCache: Initial CacheSize: 160 1
BackupStream(0): Processing MSDA of size 32 extents 0
BackupStream(1): Processing MSDA of size 32 extents 16
BackupStream(0): Completed MSDA 0
BackupStream(0): Processing MSDA of size 32 extents 0
BackupStream(1): Completed MSDA 2
Waiting for log zeroing to complete 5
BackupStream(0): Completed MSDA 66
Log zeroing is complete 0
BackupStream(0): Processing MSTL (FID=x, VLFID=xx, size=65536 bytes) 12
Data transfer is complete 4
Backup set is restored 33
Offline roll-forward begins 1
Processing 12 VLF headers 4
Processing VLF headers is complete 2
First LSN: xx:xxxxx:xx, Last LSN: xx:xxxxx:x 3
Stop LSN: xx:xxxxx:x 6
Offline roll-forward is complete 9
Database fixup is complete 5
Resuming any halted Fulltext crawls 6
Writing history records 51
Writing history records is complete (elapsed = 53 ms) 3
MSDB maintenance is complete 3
RESTORE DATABASE finished 1093
Acquired X lock on the database 0
Acquiring U lock on the database 0
Acquiring X lock on the database 0
Opening the backup set 0
RESTORE LOG started 1003
Planning begins 0
Processing the leading metadata 1
First LSN = xx:xxxx:x, Last LSN = xx:xxxxx:x 3
Beginning OFFLINE restore 0
Effective options: Checksum=0, Compression=0, Encryption=0, BufferCount=20, MaxTransferSize=2048 KB 0
Planning is complete 2
Preparing containers 1
Containers are ready 4
Estimated total size to transfer = 16384 bytes 0
FileHandleCache: Initial CacheSize: 160 0
Restoring the backup set 0
Transferring data 0
Waiting for log zeroing to complete 1
Log zeroing is complete 0
BackupStream(0): Processing MSTL (FID=2, VLFID=48, size=65536 bytes) 6
Data transfer is complete 4
Backup set is restored 11
Offline roll-forward begins 1
Processing 12 VLF headers 2
Processing VLF headers is complete 1
First LSN: xx:xxxxx:x, Last LSN: xx:xxxx:x 1
Stop LSN: xx:xxxx:x 3
Offline roll-forward is complete 7
Database fixup is complete 7
Writing history records 14
MSDB maintenance is complete 0
RESTORE LOG finished 0
Writing history records is complete (elapsed = 13 ms) 724
Acquired X lock on the database 0
Acquiring U lock on the database 0
Acquiring X lock on the database 0
RESTORE LOG started 1
Opening the backup set 1023
First LSN = xxxxxxxxxx, Last LSN = xxxxxxxxx 0
Planning begins 0
Processing the leading metadata 5
Beginning OFFLINE restore 0
Effective options: Checksum=0, Compression=0, Encryption=0, BufferCount=20, MaxTransferSize=2048 KB 0
Planning is complete 2
Preparing containers 1
Containers are ready 5
Estimated total size to transfer = 9216 bytes 0
FileHandleCache: Initial CacheSize: 160 0
Log zeroing is complete 0
Restoring the backup set 0
Transferring data 0
Waiting for log zeroing to complete 0
BackupStream(0): Processing MSTL (FID=2, VLFID=48, size=65536 bytes) 12
Data transfer is complete 5
Backup set is restored 12
Offline roll-forward begins 7
Processing 12 VLF headers 7
Processing VLF headers is complete 5
First LSN: xxxxxxx, Last LSN: xxxxxxxxxx 1
Stop LSN: xxxxxxxxx 3
Offline roll-forward is complete 14
Database fixup is complete 8
Writing history records 13
MSDB maintenance is complete 0
RESTORE LOG finished 0
Writing history records is complete (elapsed = 13 ms) 731
Acquired X lock on the database 0
Acquiring U lock on the database 0
Acquiring X lock on the database 0
RESTORE LOG started 1
Opening the backup set 1007
First LSN = xxxxxxxxx, Last LSN = xxxxxxxxx 0
Planning begins 0
Processing the leading metadata 3
Beginning OFFLINE restore 0
Effective options: Checksum=0, Compression=0, Encryption=0, BufferCount=20, MaxTransferSize=2048 KB 0
Planning is complete 2
Preparing containers 1
Containers are ready 4
Estimated total size to transfer = 2048 bytes 0
FileHandleCache: Initial CacheSize: 160 0
Log zeroing is complete 0
Restoring the backup set 0
Transferring data 0
Waiting for log zeroing to complete 0
BackupStream(0): Processing MSTL (FID=2, VLFID=48, size=65536 bytes) 8
Data transfer is complete 4
Backup set is restored 6
Offline roll-forward begins 0
Processing 12 VLF headers 4
Processing VLF headers is complete 4
First LSN: xxxxxxxxx, Last LSN: xxxxxxxxxx 1
Stop LSN: xxxxxxxxxx 2
Offline roll-forward is complete 8
Database fixup is complete 7
Writing history records 13
MSDB maintenance is complete 0
Writing history records is complete (elapsed = 13 ms) 1
RESTORE LOG finished 715
Acquired X lock on the database 0
Acquiring U lock on the database 0
Acquiring X lock on the database 0
Opening the backup set 0
RESTORE LOG started 1006
First LSN = xxxxxxxxx, Last LSN = xxxxxxxxxx 0
Planning begins 0
Processing the leading metadata 3
Beginning OFFLINE restore 0
Effective options: Checksum=0, Compression=0, Encryption=0, BufferCount=20, MaxTransferSize=2048 KB 0
Planning is complete 2
Containers are ready 0
Preparing containers 5
Estimated total size to transfer = 2048 bytes 0
FileHandleCache: Initial CacheSize: 160 0
Log zeroing is complete 0
Restoring the backup set 0
Transferring data 0
Waiting for log zeroing to complete 0
BackupStream(0): Processing MSTL (FID=2, VLFID=48, size=65536 bytes) 7
Data transfer is complete 3
Backup set is restored 7
Offline roll-forward begins 1
Processing 12 VLF headers 4
Processing VLF headers is complete 4
First LSN: xxxxxxxxxx, Last LSN: xxxxxxxxx 0
Stop LSN: xxxxxxxxx 3
Offline roll-forward is complete 7
Database fixup is complete 8
Writing history records 13
MSDB maintenance is complete 0
Writing history records is complete (elapsed = 13 ms) 1
RESTORE LOG finished 22
Acquired X lock on the database 0
Acquiring U lock on the database 0
Acquiring X lock on the database 0
RESTORE LOG started 1
Transitioning database to ONLINE 6
Restarting database for ONLINE 66
PostRestoreContainerFixups begins 5
PostRestoreContainerFixups is complete 8
PostRestoreReplicationFixup begins 93
PostRestoreReplicationFixup is complete 13
Database is restarted 1
Resuming any halted Fulltext crawls 1
RESTORE DATABASE finished 0

Read more 

How to troubleshoot Slow SQL Server Backup and Restore with DBCC TRACEON (3004, 3605, -1)

Database autogrow and slow database recovery – t-sql Tuesday 21 

 


Author: Tom Collins (http://www.sqlserver-dba.com)


Share:

Verify your Comment

Previewing your Comment

This is only a preview. Your comment has not yet been posted.

Working...
Your comment could not be posted. Error type:
Your comment has been posted. Post another comment

The letters and numbers you entered did not match the image. Please try again.

As a final step before posting your comment, enter the letters and numbers you see in the image below. This prevents automated programs from posting comments.

Having trouble reading this image? View an alternate.

Working...

Post a comment on How to capture SQL Server database RESTORE details with Extended Events


sqlserver-dba.com | SQL Server Performance Tuning | SQL Server DBA:Everything | FAQ | Contact|Copyright & Disclaimer