SQL Server Restore – History of Database Restore Completion Times

restoresql server

I'm trying to estimate the restore time for a few 1TB+ databases on SQL 2012. Is it possible to look at completed restores from the last year and list the completion time ? It's an odd remote server on the other side of the world, all I know full restores used to run every beginning of a new month, for some reason, but can't figure out how to access the history.

Best Answer

This information is not tracked in MSDB, so there's no way to find it there (unless the restore operation is in its own step in a job, in which case you could get it from msdb.dbo.sysjobhistory).

If you can't rely on job history, and it was recent enough, you can approximate it from the default trace, with the assumption that the system does something to the database as soon as the restore is completed (which happens in all of my tests, though there may be scenarios where this doesn't happen, such as restoring with norecovery or restoring a read-only database - both scenarios I didn't test):

DECLARE @path NVARCHAR(260);

SELECT 
   @path = REVERSE(SUBSTRING(REVERSE([path]), 
   CHARINDEX(CHAR(92), REVERSE([path])), 260)) + N'log.trc'
FROM    sys.traces
WHERE   is_default = 1;

SELECT *, rn = ROW_NUMBER() OVER 
  (PARTITION BY DatabaseName ORDER BY StartTime)
INTO #blat
FROM sys.fn_trace_gettable(@path, DEFAULT) 
WHERE DatabaseName IN (
  N'db1', N'db2' -- , ...
)
ORDER BY StartTime DESC; 

SELECT b.DatabaseName, b.TextData, 
  ApproximateRestoreTime = DATEDIFF(MILLISECOND, b.StartTime, b2.StartTime)
FROM #blat AS b 
LEFT OUTER JOIN #blat AS b2
ON b.DatabaseName = b2.DatabaseName
AND b2.rn = b.rn + 1
WHERE b.EventClass = 115 AND b.EventSubClass = 2
ORDER BY b.StartTime DESC;

GO
DROP TABLE #blat;

(I tried the queries in this Stack Overflow answer, but they weren't quite as efficient - you're more than welcome to try those, too, to see if they better suit your needs.)

One scenario I did test where this strategy does not work is if all of the auto-stats options are disabled - since the activity that seems to happen immediately after restore is some auto-stats operations on system tables like syscolpars and sysschobjs. This doesn't happen - even for system tables - when auto-stats are disabled.

If you have timestamps from subsequent system events immediately following the restore, you will have a rough estimation of how long the restore took, but it won't necessarily be very precise. You don't get this type of more precise information, of course, which is what gets output to the messages tab if you run a restore interactively (and it also gets written to the error log, as long as trace flag 3226 is not enabled):

RESTORE DATABASE successfully processed 291 pages in 0.021 seconds (108.258 MB/sec).

But you can still pull this info from the error log (again, as long as it happened recently enough that it hasn't been aged away). If you don't have trace flag 3226 enabled, you should see all of the messages like above in the current error log using the following query:

EXEC sp_readerrorlog 0, 1, N'Restore', N'MB/sec';

Now, you need to expand your search set once you've identified the timeframe you're after, since the message(s) above fail to include the database name. So you can trace down three sets of message from the log: when the database was marked as restoring, when the restore was complete, and the message that includes the pages and time (note that the latter might not line up with the delta between the first two if you are trying to get sub-second granularity).

CREATE TABLE #x(LogDate DATETIME, p SYSNAME, [Text] NVARCHAR(MAX));
INSERT #x EXEC sp_readerrorlog 0, 1, N'Restore', N'MB/sec';
-- repeat for 1, 2, 3, 4, 5, 6 if you want to capture more history:
--INSERT #x EXEC sp_readerrorlog 1, 1, N'Restore', N'MB/sec';
--INSERT #x EXEC sp_readerrorlog 2, 1, N'Restore', N'MB/sec';
--...

CREATE TABLE #y(LogDate DATETIME, p SYSNAME, [Text] NVARCHAR(MAX));
INSERT #y EXEC sp_readerrorlog 0, 1, N'is marked RESTORING';
-- again repeat for 1, 2, 3, 4, 5, 6 like above

CREATE TABLE #z(LogDate DATETIME, p SYSNAME, [Text] NVARCHAR(MAX));
INSERT #z EXEC sp_readerrorlog 0, 1, N'Restore is complete';
-- one more time, you may need to repeat if you want more history

SELECT LogDate, [Text]
FROM 
(
  SELECT LogDate, [Text] FROM #x
  UNION ALL SELECT LogDate, [Text] FROM #y
  UNION ALL SELECT LogDate, [Text] FROM #z
) AS xyz
ORDER BY LogDate;

GO
DROP TABLE #x, #y, #z;

If you're only after a single database, or a database name pattern, you could add a second filter to the second and third queries, e.g.:

INSERT #y EXEC sp_readerrorlog 0, 1, N'is marked RESTORING', N'database_name';

If trace flag 3226 is enabled, you will only get the first two messages, and not the third.

If you want to troubleshoot slow restore times, first of all make sure Instant File Initialization is enabled (see here and here), and you can also actively monitor the process (in addition to the STATS option, which doesn't account for undo/redo, VLF work, or MSDB/history maintenance) by enabling trace flags 3604/3605, 3004, and 3014. See this article for more details.

Related Question