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

Question

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?

Cyanic

Answer 1

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 

Dossier

That is awesome. I'll run this asap on my server(s) – Cyanic

The first query indeed returns the start time of the restores, the second query returns nothing, maybe due to a join. I'm investigating... – Cyanic

The only thing that comes to mind is if the database IDs weren't matching (because they were null) -- hopefully my edits will work for you. – Dossier

Thanks again. The edit does return rows, and I see the restore actions, but endtime is NULL for all restores. – Cyanic

@Cyanic -- Correct; during my testing, the EndTime is always NULL. To compensate for this, you should ideally get two rows per restore, one for the start of the restore, and one for the end of the restore. The StartTime of the second action should actually be the considered the end time of the restore process. If you don't like the two-row result, it should be possible to take my query and tweak it so that it only returns one row, using the StartTime of the first event as the true StartTime, and the StartTime of the second event as the aliased EndTime, if that makes sense. – Dossier

Answer 2

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

Trichocyst

Thanks. Is this really the only way? I find it hard to believe that SQL server doesn't store this information somewhere.. – Cyanic

Not the only way; just a simple way that also allows you to track differences over time, since the system stores the job history for a period of time. – Trichocyst

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!

Mayramays

Answer 4

We can get the start time of the database restore from SQL, we can find out end time from event viewer by going to windows logs - application - filter the log source MSSQLSERVER, it will have the entry when the database restoration.

Wolter