SQL Server 2016: Extended Events are more powerful as Trace Flag for Backups and Restores

Before SQL Server 2016, we use Trace Flag to display information about backup and restore operations like the 3004, 3014, 3213 or 3604.
Here a link to the MSDN with a great SQL Server trace flag list

SQL Server 2016 provides 2 new Extended Events:

• backup_restore_progress_trace
• database_backup_restore_throughput

backup_restore_progress_trace will give detailed information during the backup process and restore operation

database_backup_restore_throughput will provide different throughput about backup/restore process

Create an Extended Event for Backup & Restore operations

I create an Event Session script called “Backup Restore Information” with both events, I don’t start my event session at creation:

CREATE EVENT SESSION [Backup Restore Information] ON SERVER 
ADD EVENT sqlserver.backup_restore_progress_trace(
    ACTION(sqlserver.client_hostname,sqlserver.database_name)),
ADD EVENT sqlserver.databases_backup_restore_throughput(
    ACTION(sqlserver.client_hostname,sqlserver.database_name))
ADD TARGET package0.event_file(SET filename=N'C:\ExtendedEvent\Backup_Restore_information.xel')
WITH (STARTUP_STATE=OFF)
GO

All information are stored in a file called “Backup_Restore_information.xel”. I start now my Event session:

ALTER EVENT SESSION [Backup Restore Information] ON SERVER STATE = START

To have a good test, I downloaded the AdventuredWorks sample for SQL Server 2016 here

Restore a database

The first test is to restore the database [AdventureworksDW2016CTP3]

If I display the Extended Events, I have 1553 Events for a restore

I add the column trace_message to have more information for the event backup_restore_progress_trace

If I add a filter on the column trace_message to avoid “Null”, I have 59 events

Backup a database

Like my restore, I will do the same process with a backup operation:

If I look to the Extended Event file, I see 115 events including the 59 events for the restore, so I have 56 events for the backup with a lot of information.

I will not analyze all information but as example, you can see that the database has an S lock during read operation for the backup. You see also the checkpoint with the time when it occurred, etc.

Read the extended events file

To read the file, I use the function sys.fn_xe_file_target_read_file

SELECT 
    n.value('(@name)[1]', 'varchar(50)') AS event_name,
      DATEADD(hh, 
            DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP), 
            n.value('(@timestamp)[1]', 'datetime2')) AS [timestamp],
    n.value('(data[@name="trace_message"]/value)[1]', 'varchar(max)') as trace_message
FROM 
(SELECT
    CAST(event_data AS XML) AS event_data
 FROM sys.fn_xe_file_target_read_file('C:\ExtendedEvent\Backup_Restore_information_0_131069931247850000.xel',Null, null, null)
 
) as tab
CROSS APPLY event_data.nodes('event') as q(n)
where n.value('(data[@name="trace_message"]/value)[1]', 'varchar(max)') IS NOT NULL

To see the time in millisecond, I add an operation to do this with the timestamp:

COALESCE(DATEDIFF(MILLISECOND, n.value('(@timestamp)[1]', 'datetime2') , LEAD(n.value('(@timestamp)[1]', 'datetime2'),1) OVER (ORDER BY n.value(N'(event/action[@name="event_sequence"])[1]', N'int'))) ,0) as Duration

I also add the operation type (backup=0 and restore=1):

n.value('(data[@name="operation_type"]/value)[1]', 'int') AS operation_type

And finally, I obtain this query to filter my event file:

SELECT 
    n.value('(@name)[1]', 'varchar(50)') AS event_name,
	 n.value('(data[@name="operation_type"]/value)[1]', 'int') AS operation_type,
      DATEADD(hh, 
            DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP), 
            n.value('(@timestamp)[1]', 'datetime2')) AS [timestamp],
    n.value('(data[@name="trace_message"]/value)[1]', 'varchar(max)') as trace_message,
	COALESCE(DATEDIFF(MILLISECOND, n.value('(@timestamp)[1]', 'datetime2') , LEAD(n.value('(@timestamp)[1]', 'datetime2'),1) OVER (ORDER BY n.value(N'(event/action[@name="event_sequence"])[1]', N'int'))
	) ,0) as Duration
FROM 
(SELECT
    CAST(event_data AS XML) AS event_data
 FROM sys.fn_xe_file_target_read_file('C:\ExtendedEvent\Backup_Restore_information_0_131069931247850000.xel',Null, null, null)
 
) as tab
CROSS APPLY event_data.nodes('event') as q(n)
where n.value('(data[@name="trace_message"]/value)[1]', 'varchar(max)') IS NOT NULL

Be just careful with the result like my test. The “RESTORE DATABASE finished” has normally a value of 0. This little error comes from the LEAD command and the fact that I have a backup 22 minutes after…