SQL Server 2016 Extended Events Detailed Backup Information

By: Rajendra Gupta | Comments | Related: > SQL Server 2016

Problem

There are several ways to track SQL Server database backup and restore progress using wait stats, DMVs and trace flags, but SQL Server 2016 provides more insight using Extended Events which we will take a look at in this tip.

Solution

We can view database backup and restore progress with the sys.dm_exec_requests DMV and there also a few trace flags, such as:

Trace Flag 3014: Information regarding file creation, padding and more about a backup
Trace Flag 3004: Displays detailed information about the internal restore operation
Trace Flag 3213: Displays information related to a backup that is running such as buffer count, total amount of memory used, etc.

With this DMV and Trace Flags we can get some details, but it is difficult to track what things are occurring while a backup is running especially for large databases where the backup normally takes a long time to run.

SQL Server 2016 provides more insight using these new Extended Events:

backup_restore_progress_trace: provides backup and restore progress trace messages with details
database_backup_restore_throughput: provides databases backup and restore throughput

Configure SQL Server Extended Events for Backup and Restore

To create an Extended Events session, go to Management | Extended Events | Session and right click and select New Session Wizard.

Start a new SQL Server 2016 Extended Events session

This will open the Extended Event Session wizard.

Enter a name for the Extended Events session.

Name the SQL Server Extended Events Session

On the next page we can select a template or create a new session. We will select Do not use a template.

Select either a Template or do not use an Extended Events template

Now we can find the Extended Events with the search functionality. If you type backup, it will show both of these new Extended Events. We will select both of these.

Search for the new SQL Server 2016 Backup Extended Events

On the next screen, we can select more fields which we want to capture with the trace, here I have selected database_name and client_hostname.

Select the Global Fields to collect with the Extended Events Session

On the next screen we can specify filters.

Specify filters for the SQL Server 2016 Extended Events

Then we select how and where we want to store the Extended Events information that will be captured.

Specify the Session Data Storage for Extended Events

On the next screen we have the option to script out the actions, where we can get a script to configure the event session.

This is a screenshot of what the script looks like for the options we selected.

Script Generated for the Extended Events

Here is the actual script that was generated:

CREATE EVENT SESSION [Backup_Extended_events] ON SERVER 
ADD EVENT sqlserver.backup_restore_progress_trace(
    ACTION(sqlserver.client_hostname)),
ADD EVENT sqlserver.databases_backup_restore_throughput(
    ACTION(sqlserver.client_hostname,sqlserver.database_name))
ADD TARGET package0.event_file(SET filename=N'C:\mssqltips\backup extended event\Backup_extended_events.xel')
WITH (STARTUP_STATE=OFF)
GO

Now finish the wizard.

Start and View Extended Event Session Details

Now we will start the event session and then start a database backup as well.

ALTER EVENT SESSION [Backup_Extended_events] ON SERVER STATE = START

Initiate the backup and then we will look at the Extended Events data that was captured.

Now we will go to Extended Events session and view the data, by default it shows information like this:

Now to get more information, right click on the columns and select Choose Columns and then select the desired columns.

Select the columns to review the Extended Events data

Now we can see the additional columns we selected.

Final SQL Server Extended Events Output with the additional columns

As you can see there are a lot of rows that have NULL values. To filter the NULLS, right click and select Filter by this Value as shown below.

A new window will open where we can set the filter options.

Filter the Null values from the result set

Here is what it looks like after the filter has been applied. We can see the database backup was started and its operations along with the progress, size, etc.

Database backup details from the Extended Events

Additional database backup operations captured with Extended Events

Below are some event details of the events shown above:

Backup Database started - start of the backup operation.
Opening the database with S lock - Information about a shared lock in the database to start reading the data.
Acquiring bulk-op lock on the database - Identifies the database lock taken by the backup database.
Synchronizing with other operations on the database is complete - This step shows that if there is another operation running on the database it will be in sync.
Opening the backup media set - Now system starts the verification of the backup directory where the backup will be created as well as space to create the backup file.
The backup media set is open - If everything is fine with the step above, the backup set is open to write.
Preparing the media set for writing - At this stage the media set is prepared to start the writing process .
Effective options: Checksum = 0, Compression= 1, Encryption = 0, BufferCount = 7, MaxTransferSize = 1024 KB - At this point additional backup options are set like checksum, compression etc.
Clearing differential bitmaps - As we know differential backups use a reference point of the last full backup using bit differential bitmap. The system will clear the differential bitmap, so the next differential backup will reference this full backup, this will not be case with a copy-only backup.
Writing a checkpoint and checkpoint is complete - At this point a checkpoint is fired before starting the backup and progress is recorded on how much time it took for the checkpoint.
Start LSN: 94:2416:2, SERepl LSN:0:0:0 - At this point the starting LSN is noted after the checkpoint
Scanning allocation bitmaps - Now a scan is performed for the allocation of pages for space calculation purposes and backup size.
Calculating expected size of full data - Performing expected total size of data to be copied.
FID = 1, ExpectedExtents = 4799, IsDifferentialMapAccurate = 0 - The number of extents required to be backed up.
- TotalSize 552468480 bytes
- Estimated total size 552693760 bytes (data size = 552468480 bytes, log size = 225280 bytes)
After the work estimation is done it will start writing leading metadata to the device C:\mssqltips\backup extended event\AdventureWorks2016CTP3.bak
Data will be read from the data file and copied to memory area (MEMORYCLERK_SQLUTILITIES).
We can see the progress of the backup as a percentage, once the data file copy is done, we can see the status as initial estimated size and final size, as well as the last LSN.
It will now copy the transaction log, this is the active portion of the transaction log containing all transactions carried out after the first checkpoint and before the last checkpoint.
Once backup is done it writes the data for the tables in the msdb data that can be used for history purposes.
Now it notifies that the BACKUP DATABASE finished

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'C:\mssqltips\backup extended event\Backup_extended_events_*.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;

Review the SQL Server 2016 Extended Events with the associated Duration

Summary

This is a great new feature available with SQL Server 2016 where we can view internal backup events and duration for each event, so we can troubleshooting long running backups. In the next tip, we will look at the restore events and also see more examples for backup and restore.

Next Steps

Check out more 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