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.
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
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
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.
You can use somewhat of below script to view details of last restore for a particular database.
DECLARE @dbname sysname, @days int SET @dbname = 'DB name here' --substitute for whatever database name you want SET @days = -3 --previous number of days, script will default to 30 SELECT rsh.destination_database_name AS [Database], rsh.user_name AS [Restored By], CASE WHEN rsh.restore_type = 'D' THEN 'Database' WHEN rsh.restore_type = 'F' THEN 'File' WHEN rsh.restore_type = 'G' THEN 'Filegroup' WHEN rsh.restore_type = 'I' THEN 'Differential' WHEN rsh.restore_type = 'L' THEN 'Log' WHEN rsh.restore_type = 'V' THEN 'Verifyonly' WHEN rsh.restore_type = 'R' THEN 'Revert' ELSE rsh.restore_type END AS [Restore Type], rsh.restore_date AS [Restore Started], bmf.physical_device_name AS [Restored From], rf.destination_phys_name AS [Restored To] FROM msdb.dbo.restorehistory rsh INNER JOIN msdb.dbo.backupset bs ON rsh.backup_set_id = bs.backup_set_id INNER JOIN msdb.dbo.restorefile rf ON rsh.restore_history_id = rf.restore_history_id INNER JOIN msdb.dbo.backupmediafamily bmf ON bmf.media_set_id = bs.media_set_id WHERE rsh.restore_date >= DATEADD(dd, ISNULL(@days, -30), GETDATE()) --want to search for previous days AND destination_database_name = ISNULL(@dbname, destination_database_name) --if no dbname, then return all ORDER BY rsh.restore_history_id DESC GO
I was trolling the interwebs for a query to help me with this very issue and stumbled across this thread. Thank you Aaron for confirming that the msdb tables do not capture the restore completion time so calculating duration from that source alone is impossible! In addition to using the default trace as Aaron outlines, if you have ERRORLOGs available from around the time the restore was started and completed, you can calculate the duration another way with some tom foolery. For me, my errorlogs were much older than my default trace files, so this approach provided much more historic information for me.
I've created a script below that should do this for you, given you have the proper elevated permissions to call the extended sps:
DECLARE @NumErrorLogs INT, @i INT = 0 -- Get number of ERRORLOG files we need to iterate through EXEC master.dbo.xp_instance_regread N'HKEY_LOCAL_MACHINE', N'Software\Microsoft\MSSQLServer\MSSQLServer', N'NumErrorLogs', @NumErrorLogs OUTPUT; -- Table to capture restore completion times CREATE TABLE #tmp_Restore ( LogDate DATETIME2 , ProcessInfo NVARCHAR(250) , [Text] NVARCHAR(4000) ) -- Pull any Restore Events from available Logs WHILE @i < @NumErrorLogs BEGIN INSERT INTO #tmp_Restore EXEC xp_readerrorlog @i, 1, N'Restore is complete on database', NULL, NULL, NULL, N'desc' SELECT @i = @i + 1 END -- Create new column that will store database name parsed out from text field ALTER TABLE #tmp_Restore ADD [database] NVARCHAR(250); -- Update database name column UPDATE #tmp_Restore SET [database] = SUBSTRING([Text], 34, LEN([Text]) - CHARINDEX(N'''', [Text]) - CHARINDEX(N'''', REVERSE([Text]))) -- Build out restore order so joins match up in case a database has been restored multiple times ;WITH rh AS ( SELECT rh.destination_database_name AS database_name , rh.restore_date AS restore_start , ROW_NUMBER() OVER (PARTITION BY rh.destination_database_name ORDER BY rh.restore_date DESC) AS restore_num FROM msdb.dbo.restorehistory rh ), r AS ( SELECT r.[database] AS database_name , r.LogDate AS restore_finish , ROW_NUMBER() OVER (PARTITION BY r.[database] ORDER BY r.LogDate DESC) AS restore_num FROM #tmp_Restore r ) -- Show restore durations for those database we have available history for SELECT r.database_name , rh.restore_start , r.restore_finish , DATEDIFF(MINUTE, rh.restore_start, r.restore_finish) AS restore_duration FROM rh INNER JOIN r ON rh.database_name = r.database_name AND rh.restore_num = r.restore_num ORDER BY r.restore_finish DESC -- Cleanup DROP TABLE #tmp_Restore
Hopefully that helps someone else out down the road!