How to capture SQL Server database RESTORE details with Extended Events

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