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…