How can I query how much time a SQL server database restore takes?

Question

Hi

Im trying to write a query that will tell me how much time a restore (full or log) has taken on SQL server 2008.

I can run this query to find out how much time the backup took:

select  database_name, 
        [uncompressed_size] = backup_size/1024/1024,
        [compressed_size] = compressed_backup_size/1024/1024, 
        backup_start_date, 
        backup_finish_date, 
        datediff(s,backup_start_date,backup_finish_date) as [TimeTaken(s)], 
from    msdb..backupset b 
where   type = 'L' -- for log backups
order by b.backup_start_date desc

This query will tell me what is restored but now how much time it took:

select * from msdb..restorehistory

restorehistory has a column backup_set_id which will link to msdb..backupset, but that hold the start and end date for the backup not the restore.

Any idea where to query the start and end time for restores?

Answer 1

Make it a Job. Then run it as the Job. Then check the View Job History. Then look at the duration column.

Answer 2

To find the RESTORE DATABASE time, I have found that you can use this query:

declare @filepath nvarchar(1000) 

SELECT @filepath = cast(value as nvarchar(1000)) FROM [fn_trace_getinfo](NULL) 
WHERE [property] = 2 and traceid=1 

SELECT *
FROM [fn_trace_gettable](@filepath, DEFAULT) 
WHERE TextData LIKE 'RESTORE DATABASE%' 
ORDER BY StartTime DESC; 

The downside is, you'll notice that, at least on my test server, the EndTime is always NULL.

So, I came up with a second query to try and determine the end time. First of all, I apologize that this is pretty ugly and nested like crazy.

The query below assumes the following:

1. When a restore is run, for that DatabaseID and ClientProcessID, the next EventSequence contains the TransactionID we need.
2. I then go and find the max EventSequence for the Transaction
3. Finally, I select the record that contains RESTORE DATABASE and the maximum transaction associated with that record.

I'm sure someone can probably take what I've done and refine it, but this appears to work on my test environment:

declare @filepath nvarchar(1000) 

SELECT @filepath = cast(value as nvarchar(1000)) FROM [fn_trace_getinfo](NULL) 
WHERE [property] = 2 and traceid=1 

SELECT *
FROM [fn_trace_gettable](@filepath, DEFAULT) F5
INNER JOIN 
(
    SELECT F4.EventSequence MainSequence, 
         MAX(F3.EventSequence) MaxEventSequence, F3.TransactionID
    FROM [fn_trace_gettable](@filepath, DEFAULT) F3
    INNER JOIN 
    (
        SELECT F2.EventSequence, MIN(TransactionID) as TransactionID
        FROM [fn_trace_gettable](@filepath, DEFAULT) F1
        INNER JOIN 
        (
            SELECT DatabaseID, SPID, StartTime, ClientProcessID, EventSequence
            FROM [fn_trace_gettable](@filepath, DEFAULT)
            WHERE TextData LIKE 'RESTORE DATABASE%' 
        ) F2 ON F1.DatabaseID = F2.DatabaseID AND F1.SPID = F2.SPID 
                       AND F1.ClientProcessID = F2.ClientProcessID 
                       AND F1.StartTime > F2.StartTime
        GROUP BY F2.EventSequence
    ) F4 ON F3.TransactionID = F4.TransactionID 
    GROUP BY F3.TransactionID, F4.EventSequence
) F6 ON F5.EventSequence = F6.MainSequence 
    OR F5.EventSequence = F6.MaxEventSequence
ORDER BY F5.StartTime

EDIT

I made some changes to the query, since one of the test databases I used is case-sensitive and it was losing some records. I also noticed when restoring from disk that the DatabaseID is null, so I'm handling that now as well:

SELECT * 
FROM [fn_trace_gettable](@filepath, DEFAULT) F5 
INNER JOIN  
( 
    SELECT F4.EventSequence MainSequence,  
         MAX(F3.EventSequence) MaxEventSequence, F3.TransactionID 
    FROM [fn_trace_gettable](@filepath, DEFAULT) F3 
    INNER JOIN  
    ( 
        SELECT F2.EventSequence, MIN(TransactionID) as TransactionID 
        FROM [fn_trace_gettable](@filepath, DEFAULT) F1 
        INNER JOIN  
        ( 
            SELECT DatabaseID, SPID, StartTime, ClientProcessID, EventSequence 
            FROM [fn_trace_gettable](@filepath, DEFAULT) 
            WHERE upper(convert(nvarchar(max), TextData)) 
                LIKE 'RESTORE DATABASE%'  
        ) F2 ON (F1.DatabaseID = F2.DatabaseID OR F2.DatabaseID IS NULL) 
                   AND F1.SPID = F2.SPID  
                   AND F1.ClientProcessID = F2.ClientProcessID  
                   AND F1.StartTime > F2.StartTime 
        GROUP BY F2.EventSequence 
    ) F4 ON F3.TransactionID = F4.TransactionID  
    GROUP BY F3.TransactionID, F4.EventSequence 
) F6 ON F5.EventSequence = F6.MainSequence  
    OR F5.EventSequence = F6.MaxEventSequence 
ORDER BY F5.StartTime 

Answer 3

While it is running you can check something like this dmv.

select 
d.name
,percent_complete
,dateadd(second,estimated_completion_time/1000, getdate())
, Getdate() as now
,datediff(minute, start_time
, getdate()) as running
, estimated_completion_time/1000/60 as togo
,start_time
, command 
from sys.dm_exec_requests req
inner join sys.sysdatabases d on d.dbid = req.database_id
where 
req.command LIKE '%RESTORE%'

Or you can use some magic voodoo and interpret the transaction log in the following table function, however the only person I know to understand any info in this log is Paul Randal. I Know he sometimes checks Server Fault, but don't know if he wonders StackOverflow.

select * from fn_dblog(NULL,NULL)

Hope this helps. If you manage to use this and find a solution please tell us.

Good Luck!