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.
This will open the Extended Event Session wizard.
Enter a name for the 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.
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.
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.
On the next screen we can specify filters.
Then we select how and where we want to store the Extended Events information that will be captured.
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.
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.
Now we can see the additional columns we selected.
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.
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.
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;
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
