5

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.

15

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.

  • Nice Aaron, very helpful information. Got the name of the database with: SELECT * FROM msdb..restorehistory EXEC xp_readerrorlog 0, 1, N'database is now available.' – Razvan Zoitanu May 13 '15 at 9:09
2

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
  • 1
    Thank you, but msdb..restorehistory only shows the restore start date. I'd like to get the duration of each restore. – Razvan Zoitanu May 12 '15 at 14:51
1

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!

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.