Capture Detailed SQL Server Restore Steps with Extended Events

Problem

As seen in this previous tip, SQL Server 2016 Extended Events Detailed Backup Information, we can get a lot of insight for database backup operations and troubleshooting. Similarly SQL Server 2016 also provides Extended Events for database restores too, which we will explore in this tip.

Solution

As highlighted below, SQL Server 2016 provides new functionality for backup and restore information using these Extended Events:

• backup_restore_progress_trace: shows backup/restore progress trace messages with details
• database_backup_restore_throughput: shows databases backup/restore throughput

We can create the Extended Event session for capturing the restore operation as per the below script:

CREATE EVENT SESSION [test] ON SERVER 
ADD EVENT sqlserver.backup_restore_progress_trace
   (WHERE [operation_type] = 1 )   -- Filter for restore operation
ADD TARGET package0.event_file(SET filename=N'test')
WITH (STARTUP_STATE=OFF)
GO

For the restore operation we will test two scenarios:

1. Restore database as a new database
2. Restore database over an existing database

Restore Database as a New SQL Server Database

Once we have restored the database we can view the Extended Events captured as shown below:

Let’s discuss these events:

• RESTORE DATABASE started – Start of the database restore operation.
• Opening Backup Set – Database server will open access to the backup media.
• Processing the leading metadata – Backup media meta data will be read to start restore planning.
• Planning begins – Planning will be started on how the restore needs to be carried out.
• Effective options: Checksum = 0, Compression=0, Encryption = 0, BufferCount = 6, MaxTransferSize = 64KB: – this step shows the options used for the restore such as checksum, compression, encryption, etc.
• Planning is complete – Planning is completed for the database restore.
• Beginning restore OFFLINE – Database restore will begin.
• Attached the database DB_ID = 9 – Since we are restoring as a new database a new DBID will be assigned.
• Preparing containers – Database containers such as database files and file groups will be created.
• Restoring the Backup Set – Now the database restore will be started and it will show how much data is expected to be restored in bytes. Now the system will start showing progress of database restore in percentage terms along with the database size progressed/total bytes needs to be processed.
• Waiting for zeroing to complete log – Allocation of the log files will be completed and will be reset since the log files don’t have any instant file initialization, so once done it will show event as log zeroing is done.
• Backup Stream (0): Processing MSTL (FID = 2, VLFID = 40, size = 65536 bytes) – Indicate the active part of the log files.
• Now data transfer is complete – Data is copied to data files and log files.
• Offline roll forward begins – Transactions will be rolled forward and the corresponding entry will be logged with first LSN and last LSN.
• Once roll forward is complete, the database will be online.
• Transition to ONLINE status to finalize the restore.
• Now final post restore cleanup will be done for replication, change data capture and the database is restarted.
• If there are any full text crawls they will resume.
• Now history will be recorded in the msdb system tables and user will be notified about completion of restore operation.

Restore Database over an Existing SQL Server Database

Now we can see the behavior for a restore when the database already exists. For the most part the steps will be similar except for some of the first steps where database locks are required before starting the restore as shown below.

Getting Durations for Restore Operations

To get specific details as how much time was spent on each operation, we can use the below query (reference http://sqlperformance.com/2015/06/extended-events/t-sql-tuesday-67-backup-restore).

;WITH xevent AS 
(
  SELECT timestamp,operation_type,database_name,trace_message,event_sequence
  FROM 
  (
   SELECT 
    timestamp  = xevent.value(N'(event/@timestamp)[1]', N'datetime2'),
    operation_type  = xevent.value(N'(event/data[@name="operation_type"]/text)[1]', N'nvarchar(32)'),
    database_name  = xevent.value(N'(event/data[@name="database_name"])[1]', N'nvarchar(128)'),
    trace_message = xevent.value(N'(event/data[@name="trace_message"])[1]', N'nvarchar(max)'),
    event_sequence  = xevent.value(N'(event/action[@name="event_sequence"])[1]', N'int')
   FROM 
   (
    SELECT xevent = CONVERT(XML, event_data) 
     FROM sys.fn_xe_file_target_read_file
          (N'test_*.xel', NULL, NULL, NULL)
   ) AS y
  ) AS xevent
 
)
SELECT 
  [Message] = xevent.trace_message, 
  Duration = COALESCE(DATEDIFF(MILLISECOND, xevent.timestamp, 
             LEAD(xevent.timestamp, 1) OVER(ORDER BY event_sequence)),0)
FROM xevent
ORDER BY event_sequence;
 

Output is as follows:

So with these Extended Events, we can get in-depth details about the database restore and troubleshoot any bottlenecks, especially for large databases or restore operations that take a long time.

Next Steps

• Download and explore SQL Server 2016 Release candidate 3.
• Read more about SQL Server 2016 Release Notes.
• Check out more SQL Server 2016 tips.
• Read more about Extended Events.