Understanding database recovery with SQL Server 2016 Extended Events

By: Rajendra Gupta | Comments | Related: > Extended Events

Problem

Sometimes after a SQL Server restart you see that database recovery takes a long time and you want to know what is causing the delay. Up until SQL Server 2014 we could get some info from the SQL Server error log, but in SQL Server 2016 we can get much more insight with Extended Events.

Solution

In my earlier tips we have seen how Extended Events in SQL Server 2016 are useful for tracking Backup and Restore operations.

Normally we used to track database recovery using the SQL Server Error Log which shows messages like:

SQL Server Database Recovery in the Error Logs

SQL Server 2016 provides 3 Extended Events for capturing more information for database recovery:

Database_recovery_progress_report

Database_recovery_times

Database_recovery_trace

First let's create a Extended Events sessions which will capture the details, this can be done with both SQL Server Management Studio (SSMS) or a T-SQL query.

Create SQL Server Extended Events Session

In SSMS, right click on Management > Extended Events > Sessions > New Session Wizard.

Start a new SQL Server Extended Events Session in SSMS

Choose a template for the SQL Server Extended Events Session

We can search the database_recovery events through a search, which shows 3 events as shown below. We can also see the Extended Events details and the fields that are captured for each event.

Extended Events for SQL Server database recovery

Select events to capture in the Extended Events Section

See the events for the database_recovery_trace event

In the next screen, we can set additional fields to capture with the default fields. I have selected database_name and event_sequence.

Set additional fields to be captured for the Extended Events

In next screen, select the location and size of the file along with the maximum number of files.

Specify the Session Data Storage for the Extended Events session

Verify the settings and events in the next summary page. We can see that Auto Start is set to off, this means if the SQL service restarts it will not automatically start capturing the events.

View the Settings and Events Summary Page for SQL Server Extended Events

We can also generate the query from the script options.

CREATE EVENT SESSION [Database_Recovery_Xevents] ON SERVER 
ADD EVENT sqlserver.database_recovery_progress_report(
    ACTION(package0.event_sequence,sqlserver.database_name)),
ADD EVENT sqlserver.database_recovery_times(
    ACTION(package0.event_sequence,sqlserver.database_name)),
ADD EVENT sqlserver.database_recovery_trace(
    ACTION(package0.event_sequence,sqlserver.database_name))
ADD TARGET package0.event_file(SET filename=N'Database_Recovery_Xevents')
WITH (STARTUP_STATE=OFF)
GO

Successfully starting the Create Events Session in SSMS

To start the Extended Events session with a SQL Server restart, edit the session and enable the "Start the event session at server startup" check box.

Schedule the Extended Event to start at server startup

This can also be done using the following T-SQL command:

ALTER EVENT SESSION [Database_Recovery_Xevents] ON SERVER 
WITH (STARTUP_STATE=ON)
GO

SQL Server Database Recovery Information

As you may know, database recovery in SQL Server consists of the following phases:

Pre-Recovery

Analysis

Redo

Undo

Complete

Post- Recovery

I have the Extended Events session running, I ran some queries in the Adventureworks database to generate a workload and then restarted the SQL Server Service. Now we will look at the events that were captured.

By default, the event log shows the name and timestamp only, so we will select additional columns here.

Choose additional columns to review with SQL Server Extended Events

Also, we will do analysis for just the Adventureworks database (this is database_id 8 on my server) and the event name of database_recovery_progress_report.

Filter the Extended Events data for the Adventureworks database

We can see the output below shows details about the recovery phase, elapsed time remaining, percent_complete and total elapsed time in seconds.

Review the database recovery phase, elapsed time remaining, percent_complete and total elapsed time in seconds.

Similarly if we want to see the database_recovery_times events, then change the filter accordingly and it will show the output as follows. As we can see with database_recovery_times events we can get recovery time for specific steps during the database startup.

database_recovery_times events we can get recovery time for specific steps during the database startup

Now if we want further detailed information about recovery, set the filter for database_recovery_trace and analyze these events.

Filter the Extended Events data for a specific database id

Here we can see more details of the start recovery process.

Start of the SQL Server Recovery Process captured by the Extended Events

Additional events captured for the recovery process

RecoveryUnit and Undo Transactions captured as a part of the recovery process

Transactions rolled back to SQL Server Recovery Complete

As seen above we can get details about each phase, some of the important events are:

Virtual log file summary
Estimated log amount for analysis
Preparation of 'Dirty Page Table' (DPT) and 'Active Transaction Table' (ATT)
Rolling forward all the changes that took place with estimated transaction log and transactions
Undo phases of the transactions with details
Recovery completion progress
Post recovery operations

We can analyze the information for our databases which can help us to understand if recovery time is longer for a database.

Next Steps

Check out SQL Server 2016 tips
Read more about Extended Events

About the author

Rajendra Gupta is a Consultant DBA with 14+ years of extensive experience in database administration including large critical OLAP, OLTP, Reporting and SharePoint databases.

This author pledges the content of this article is based on professional experience and not AI generated.

View all my tips