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

SQL2016_backup00
backup_restore_progress_trace will give detailed information during the backup process and restore operation
SQL2016_backup01
database_backup_restore_throughput will provide different throughput about backup/restore process
SQL2016_backup02

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:

1
2
3
4
5
6
7
8
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:

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

SQL2016_backup03
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]
SQL2016_backup04
If I display the Extended Events, I have 1553 Events for a restore
SQL2016_backup05
I add the column trace_message to have more information for the event backup_restore_progress_trace
SQL2016_backup06
If I add a filter on the column trace_message to avoid “Null”, I have 59 events
SQL2016_backup07

Backup a database

Like my restore, I will do the same process with a backup operation:
SQL2016_backup08
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.
SQL2016_backup09

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

1
2
3
4
5
6
7
8
9
10
11
12
13
14
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

SQL2016_backup10

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

1
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):

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

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

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
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

SQL2016_backup11

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…

Post Views: 963
Thumbnail [60x60]
by
Stéphane Haby