How to generate report on database restore durations

agargagarg Posts: 11 Bronze 2
edited May 16, 2013 1:01PM in SQL Backup Previous Versions
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.
· Share on Twitter

Comments

  • Eddie DEddie D Posts: 1,803 Rose Gold 5
    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
    Eddie Davis
    Senior Product Support Engineer
    Redgate Software Ltd
    Email: support@red-gate.com
    · Share on Twitter
  • peteypetey Posts: 2,358 New member
    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'
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
    · Share on Twitter
  • agargagarg Posts: 11 Bronze 2
    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.
    · Share on Twitter
  • peteypetey Posts: 2,358 New member
    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.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
    · Share on Twitter
  • agargagarg Posts: 11 Bronze 2
    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.
    · Share on Twitter
  • peteypetey Posts: 2,358 New member
    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?
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
    · Share on Twitter
  • agargagarg Posts: 11 Bronze 2
    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]
    · Share on Twitter
  • agargagarg Posts: 11 Bronze 2
    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
    · Share on Twitter
  • peteypetey Posts: 2,358 New member
    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).
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
    · Share on Twitter
  • agargagarg Posts: 11 Bronze 2
    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
    · Share on Twitter
Sign In or Register to comment.