How to generate report on database restore durations

agarg

I want to generate a report of the log restores of a database. The GUI has an option to generate the backup history but not the restore history. I am trying to troubleshoot something and this is needed. I can see all the logs in the GUI in the Activity History pane, but don't want to copy/paste. Any possibilities? Through GUI or sql query? Of course, I am talking about log backups taken using RedGate.

Eddie D

Hi

Thank you for your forum post.

Sadly the reporting feature of SQL Backup Pro does not generate reports on restore tasks.

I have added the details of this forum post to an existing feature request whose reference is SB-4562.

Hopefully you may see this feature in a future version of the product.

Many Thanks
Eddie

petey

If you don't mind writing your own reports, you can access the restore details using SQL commands from within Management Studio.

The SQL Backup restore history details are stored in a SQL Server Compact Edition database on the server. You could use the sqbdata proxy function to access the details. The tables that store the restore history details are:

- restorehistory
- restorefiles
- restorelog

A simple query to retrieve the restore details could be as follows:

EXEC master..sqbdata 'SELECT dbname, restore_start, restore_end FROM restorehistory WHERE restore_type = ''L'' ORDER BY dbname, restore_start'

agarg

I prefer writing my own reports - thanks for the tip. This gives me all the information I need. I need a clarification though. The following is the output from a log file. As you can see, the restore started at 9:14:18pm and finished at 9:36:59pm - that is in 22 min 36 sec. What does 313.414 seconds (in the RESTORE LOG line) signify here then?


SQL Backup log file 7.3.0.57

-SQL "RESTORE LOG DW FROM DISK = 'T:\MSSQL\TLogs\DW_Log201305111456.trn' WITH DISCONNECT_EXISTING, STANDBY = 'T:\MSSQL\TLogs\DW_undoLog.log' "

---

PROCESSES COMPLETED SUCCESSFULLY

---

5/11/2013 9:14:18 PM: Restoring DW (transaction logs) on SQL042_1 instance from:
5/11/2013 9:14:18 PM: T:\MSSQL\TLogs\DW_Log201305111456.trn

5/11/2013 9:14:19 PM: ALTER DATABASE [DW] SET ONLINE RESTORE LOG [DW] FROM
VIRTUAL_DEVICE = 'SQLBACKUP_F758110E-23D1-46DC-B4A7-6422BCBC8113',
VIRTUAL_DEVICE = 'SQLBACKUP_F758110E-23D1-46DC-B4A7-6422BCBC811301',
VIRTUAL_DEVICE = 'SQLBACKUP_F758110E-23D1-46DC-B4A7-6422BCBC811302',
VIRTUAL_DEVICE = 'SQLBACKUP_F758110E-23D1-46DC-B4A7-6422BCBC811303'
WITH BUFFERCOUNT = 24, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576 , STANDBY = N'T:\MSSQL\TLogs\DW_undoLog.log'

5/11/2013 9:36:59 PM: Processed 0 pages for database 'DW', file 'DW' on file 1.
5/11/2013 9:36:59 PM: Processed 0 pages for database 'DW', file 'DW2' on file 1.
5/11/2013 9:36:59 PM: Processed 0 pages for database 'DW', file 'DW3' on file 1.
5/11/2013 9:36:59 PM: Processed 22082859 pages for database 'DW', file 'DW_log' on file 1.
5/11/2013 9:36:59 PM: RESTORE LOG successfully processed 22082859 pages in 313.414 seconds (550.461 MB/sec).

5/11/2013 9:36:59 PM: SQL Backup process ended.

petey

The 313.414 seconds is the time taken to read and restore the backup data. The rest of the time would be used to re-apply the uncommitted transactions from the redo log prior to the restore process, and also to undo any open transactions from the current restore process, and write them to the redo log.

If you want to confirm that this is indeed the case, try restoring a couple of trx logs with the NORECOVERY option. The total duration taken should be close to what SQL Server reports on the 'RESTORE LOG successfully processed...' line.

agarg

Thanks Peter. Restoring with norecovery has indeed brought the restore times down, but not to the level I would have expected. Look at this log for example. Restore log line tells that it took 0.196 seconds, yet the total duration is 20 seconds. What could be the reason?

SQL Backup log file 7.3.0.57

-SQL "RESTORE LOG ODHR FROM DISK = 'Z:\WrkFolder\ODHR_Log201305132240.trn' WITH DISCONNECT_EXISTING, NORECOVERY "

---

PROCESSES COMPLETED SUCCESSFULLY

---

5/14/2013 12:10:07 PM: Restoring ODHR (transaction logs) from:
5/14/2013 12:10:07 PM: Z:\WrkFolder\ODHR_Log201305132240.trn

5/14/2013 12:10:07 PM: RESTORE LOG [ODHR] FROM
VIRTUAL_DEVICE = 'SQLBACKUP_6204C411-C9A0-4561-BB51-22925D632DFC',
VIRTUAL_DEVICE = 'SQLBACKUP_6204C411-C9A0-4561-BB51-22925D632DFC01',
VIRTUAL_DEVICE = 'SQLBACKUP_6204C411-C9A0-4561-BB51-22925D632DFC02',
VIRTUAL_DEVICE = 'SQLBACKUP_6204C411-C9A0-4561-BB51-22925D632DFC03'
WITH BUFFERCOUNT = 24, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576 , NORECOVERY

5/14/2013 12:10:27 PM: Processed 0 pages for database 'ODHR', file 'ownersSQL_dat' on file 1.
5/14/2013 12:10:27 PM: Processed 9091 pages for database 'ODHR', file 'ownersSQL_log' on file 1.
5/14/2013 12:10:27 PM: RESTORE LOG successfully processed 9091 pages in 0.196 seconds (362.337 MB/sec).

5/14/2013 12:10:27 PM: SQL Backup process ended.

petey

There is a trace flag you can use to log the restore process in detail. Try this:

DBCC TRACEON (3004, 3605, -1)

SQL Server will then log the additional details to the error log. Do the details explain why the restore process is taking longer than the reported duration?

agarg

Thanks Peter for sticking with me. So, I set the trace flags on and reran the restore. Here is the typical log file. Also see the attached image from sql server error logs for the activity while this particular trn log was being restored.

SQL Backup log file 7.3.0.57

-SQL "RESTORE LOG ODHR FROM DISK = 'Z:\WrkFolder\ODHR_Log201305131409.trn' WITH DISCONNECT_EXISTING, NORECOVERY "

---

PROCESSES COMPLETED SUCCESSFULLY

---

5/15/2013 11:06:01 AM: Restoring ODHR (transaction logs) from:
5/15/2013 11:06:01 AM: Z:\WrkFolder\ODHR_Log201305131409.trn

5/15/2013 11:06:01 AM: RESTORE LOG [ODHR] FROM
VIRTUAL_DEVICE = 'SQLBACKUP_40E17D6B-2515-4AA7-89DC-E17B6C50AC90',
VIRTUAL_DEVICE = 'SQLBACKUP_40E17D6B-2515-4AA7-89DC-E17B6C50AC9001',
VIRTUAL_DEVICE = 'SQLBACKUP_40E17D6B-2515-4AA7-89DC-E17B6C50AC9002',
VIRTUAL_DEVICE = 'SQLBACKUP_40E17D6B-2515-4AA7-89DC-E17B6C50AC9003'
WITH BUFFERCOUNT = 24, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576 , NORECOVERY

5/15/2013 11:06:18 AM: Processed 0 pages for database 'ODHR', file 'ownersSQL_dat' on file 1.
5/15/2013 11:06:18 AM: Processed 9400 pages for database 'ODHR', file 'ownersSQL_log' on file 1.
5/15/2013 11:06:18 AM: RESTORE LOG successfully processed 9400 pages in 0.204 seconds (359.966 MB/sec).

5/15/2013 11:06:18 AM: SQL Backup process ended.


[img]C:\temp\FastStone\ODHRRestore.jpg[/img]

agarg

Don't understand how to upload an image. So, here is the log copy/pasted from ERRORLOG:

2013-05-15 11:06:01.90 spid61 RestoreLog: Database ODHR
2013-05-15 11:06:01.90 spid61 X-locking database: ODHR
2013-05-15 11:06:01.90 spid61 Opening backup set
2013-05-15 11:06:01.94 spid61 Restore: Configuration section loaded
2013-05-15 11:06:01.94 spid61 Restore: Backup set is open
2013-05-15 11:06:01.94 spid61 Restore: Planning begins
2013-05-15 11:06:01.94 spid61 Dismounting FullText catalogs
2013-05-15 11:06:01.94 spid61 Restore: Planning complete
2013-05-15 11:06:01.94 spid61 Restore: BeginRestore (offline) on ODHR
2013-05-15 11:06:02.00 spid61 Restore: PreparingContainers
2013-05-15 11:06:02.00 spid61 Restore: Containers are ready
2013-05-15 11:06:02.00 spid61 Restore: Restoring backup set
2013-05-15 11:06:02.00 spid61 Restore: Transferring data to ODHR
2013-05-15 11:06:02.00 spid61 Restore: Waiting for log zero on ODHR
2013-05-15 11:06:02.00 spid61 Restore: LogZero complete
2013-05-15 11:06:02.21 spid61 FileHandleCache: 0 files opened. CacheSize: 48
2013-05-15 11:06:02.21 spid61 Restore: Data transfer complete on ODHR
2013-05-15 11:06:02.21 spid61 Restore: Backup set restored
2013-05-15 11:06:02.21 spid61 Restore-Redo begins on database ODHR
2013-05-15 11:06:18.84 spid61 Rollforward complete on database ODHR
2013-05-15 11:06:18.84 spid61 Restore: Done with fixups
2013-05-15 11:06:18.84 spid61 Restore: Writing history records
2013-05-15 11:06:18.84 Backup Log was restored. Database: ODHR, creation date(time): 2013/02/28(19:47:47), first LSN: 1440831:20705:1, last LSN: 1440832:29672:1, number of dump devices: 4, device information: (FILE=1, TYPE=VIRTUAL_DEVICE: {'SQLBACKUP_40E17D6B-2515-4AA7-89DC-E17B6C50AC90', 'SQLBACKUP_40E17D6B-2515-4AA7-89DC-E17B6C50AC9001', 'SQLBACKUP_40E17D6B-2515-4AA7-89DC-E17B6C50AC9002', 'SQLBACKUP_40E17D6B-2515-4AA7-89DC-E17B6C50AC9003'}). This is an informational message. No user action is required.
2013-05-15 11:06:18.84 spid61 Writing backup history records
2013-05-15 11:06:18.86 spid61 Restore: Done with MSDB maintenance
2013-05-15 11:06:18.86 spid61 RestoreLog: Finished

petey

The longest process is this entry:

2013-05-15 11:06:02.21 spid61 Restore-Redo begins on database ODHR

and this post explains what is actually done during this process:

http://msdn.microsoft.com/en-us/library ... (v=sql.105).aspx

The Restore-Redo process might just be taking a reasonable duration, or it might actually be slow, depending on your setup. If you think it should complete faster, one option may be to look at the virtual log files (VLFs) of your database (see http://adventuresinsql.com/?p=12).

agarg

Thanks Peter. I am going to change my process to restore with norecovery by default, and then recover to standby mode only in the end. That should bring down the total restore time. Also, I looked at the VLFs and resized the log file. Will watch over next few days to see the results.

Will update later. Thanks for all your help.

Ajay