restore time VERY slow (compared to native SQL restore)

dhtuckerdhtucker Posts: 41 Bronze 3
edited August 12, 2010 8:55AM in SQL Backup Previous Versions
SQL Backup 6.4.0.56 running on WinSrv2003 R2

Restoring a database roughly 10Gb in size from a .sqb file takes avg 43min, compared to 1min for a native .bak restore.

First restored from network storage: 41min. Ok, maybe network I/O adds to the restore time, and it was compression level 4.

Ran a second backup (local copy, compression level 1) and restored from that: 46min! I have no idea why it'd take it longer to restore a local copy with less compression.

Compared to SSMS backup/restore (local storage): 3min backup, 1min restore. Same server, same time of day (server loading conditions).
Doug Tucker
Database Administrator / Software Engineer
Nelnet Business Solutions - FACTS-SIS
«1

Comments

  • peteypetey Posts: 2,358 New member
    Could you please post the contents of the SQL Backup log for the backup and restore task that you performed on the local copy using compression level 1? The default folder where the logs are stored is C:\Documents and Settings\All Users\Application Data\Red Gate\SQL Backup\Log\<instance name>.

    Could you also post the output from SQL Server when you perform a native backup and restore i.e. the parts that say 'processed x no. of pages ...'.

    Thanks.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
  • dhtuckerdhtucker Posts: 41 Bronze 3
    Sorry, I listed the wrong version: 6.4.0.1012 (beta)
    Doug Tucker
    Database Administrator / Software Engineer
    Nelnet Business Solutions - FACTS-SIS
  • dhtuckerdhtucker Posts: 41 Bronze 3
    BACKUP DATABASE [BHCS_IA]
    TO DISK = N'C:\Program Files\Microsoft SQL Server\MSSQL10.MSSQLSERVER\MSSQL\Backup\bhcs_ia.bak'
    WITH NOFORMAT, NOINIT, NAME = N'BHCS_IA-Full Database Backup', SKIP, NOREWIND, NOUNLOAD, STATS = 10
    GO

    ========
    Processed 1023888 pages for database 'BHCS_IA', file 'CSSC_Data' on file 1.
    100 percent processed.
    Processed 4 pages for database 'BHCS_IA', file 'CSSC_Log' on file 1.
    BACKUP DATABASE successfully processed 1023892 pages in 241.622 seconds (33.106 MB/sec).
    ========


    RESTORE DATABASE [_bhcs_ia_bak]
    FROM DISK = N'C:\Program Files\Microsoft SQL Server\MSSQL10.MSSQLSERVER\MSSQL\Backup\bhcs_ia.bak'
    WITH FILE = 1,
    MOVE N'CSSC_Data' TO N'C:\Program Files\Microsoft SQL Server\MSSQL10.MSSQLSERVER\MSSQL\DATA\_bhcs_ia_bak.mdf',
    MOVE N'CSSC_Log' TO N'C:\Program Files\Microsoft SQL Server\MSSQL10.MSSQLSERVER\MSSQL\DATA\_bhcs_ia_bak_1.LDF',
    NOUNLOAD, STATS = 10
    GO

    ========
    Processed 1023888 pages for database '_bhcs_ia_bak', file 'CSSC_Data' on file 1.
    Processed 4 pages for database '_bhcs_ia_bak', file 'CSSC_Log' on file 1.
    RESTORE DATABASE successfully processed 1023892 pages in 254.499 seconds (31.430 MB/sec).
    ========



    SQL Backup log file 6.4.0.1012

    -SQL "BACKUP DATABASE [_app6_bhcs_ia] TO DISK = 'C:\Program Files\Microsoft SQL Server\MSSQL10.MSSQLSERVER\MSSQL\Backup\<AUTO>.sqb' WITH DISKRETRYINTERVAL = 30, DISKRETRYCOUNT = 10, THREADCOUNT = 3 "

    PROCESSES COMPLETED SUCCESSFULLY

    8/3/2010 3:42:04 PM: Backing up _app6_bhcs_ia (full database) to:
    8/3/2010 3:42:04 PM: C:\Program Files\Microsoft SQL Server\MSSQL10.MSSQLSERVER\MSSQL\Backup\EWHSERVER708__app6_bhcs_ia_FULL_201008031542.sqb

    8/3/2010 3:42:05 PM: BACKUP DATABASE [_app6_bhcs_ia] TO VIRTUAL_DEVICE = 'SQLBACKUP_60F22B92-3EBF-4969-AD98-169D641EB152', VIRTUAL_DEVICE = 'SQLBACKUP_60F22B92-3EBF-4969-AD98-169D641EB15201', VIRTUAL_DEVICE = 'SQLBACKUP_60F22B92-3EBF-4969-AD98-169D641EB15
    202' WITH BUFFERCOUNT = 18, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (_app6_bhcs_ia), 8/3/2010 3:42:04 PM', DESCRIPTION = N'Backup on 8/3/2010 3:42:04 PM Server: EWHSERVER708 Database: _app6_bhcs_ia', FORMAT

    8/3/2010 3:43:36 PM: Database size : 10.404 GB
    8/3/2010 3:43:36 PM: Compressed data size: 1.596 GB
    8/3/2010 3:43:36 PM: Compression rate : 84.66%

    8/3/2010 3:43:36 PM: Processed 1023728 pages for database '_app6_bhcs_ia', file 'CSSC_Data' on file 1.
    8/3/2010 3:43:36 PM: Processed 2 pages for database '_app6_bhcs_ia', file 'CSSC_Log' on file 1.
    8/3/2010 3:43:36 PM: BACKUP DATABASE successfully processed 1023730 pages in 91.578 seconds (87.334 MB/sec).
    8/3/2010 3:43:37 PM: SQL Backup process ended.



    SQL Backup log file 6.4.0.1012

    -SQL "RESTORE DATABASE [_app6_hbcs_ia2] FROM DISK = 'C:\Program Files\Microsoft SQL Server\MSSQL10.MSSQLSERVER\MSSQL\Backup\EWHSERVER708__app6_bhcs_ia_FULL_201008031542.sqb' WITH RECOVERY, MOVE 'CSSC_Data' TO 'C:\Program Files\Microsoft SQL
    Server\MSSQL10.MSSQLSERVER\MSSQL\Data\_app6_hbcs_ia2.mdf', MOVE 'CSSC_Log' TO 'C:\Program Files\Microsoft SQL Server\MSSQL10.MSSQLSERVER\MSSQL\Data\_app6_hbcs_ia2_log.LDF' "

    PROCESSES COMPLETED SUCCESSFULLY

    8/3/2010 5:24:22 PM: Restoring _app6_hbcs_ia2 (database) from:
    8/3/2010 5:24:22 PM: C:\Program Files\Microsoft SQL Server\MSSQL10.MSSQLSERVER\MSSQL\Backup\EWHSERVER708__app6_bhcs_ia_FULL_201008031542.sqb

    8/3/2010 5:24:22 PM: RESTORE DATABASE [_app6_hbcs_ia2] FROM VIRTUAL_DEVICE = 'SQLBACKUP_C30A28F5-F368-4CD1-BB7D-4D4ED9BB7A0A', VIRTUAL_DEVICE = 'SQLBACKUP_C30A28F5-F368-4CD1-BB7D-4D4ED9BB7A0A01', VIRTUAL_DEVICE = 'SQLBACKUP_C30A28F5-F368-4CD1-BB7D-4D4ED9B
    B7A0A02' WITH BUFFERCOUNT = 18, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576 , RECOVERY, MOVE 'CSSC_Data' TO 'C:\Program Files\Microsoft SQL Server\MSSQL10.MSSQLSERVER\MSSQL\Data\_app6_hbcs_ia2.mdf', MOVE 'CSSC_Log' TO 'C:\Program Files\Microsoft SQL
    Server\MSSQL10.MSSQLSERVER\MSSQL\Data\_app6_hbcs_ia2_log.LDF'

    8/3/2010 6:08:03 PM: Processed 1023728 pages for database '_app6_hbcs_ia2', file 'CSSC_Data' on file 1.
    8/3/2010 6:08:03 PM: Processed 2 pages for database '_app6_hbcs_ia2', file 'CSSC_Log' on file 1.
    8/3/2010 6:08:03 PM: RESTORE DATABASE successfully processed 1023730 pages in 2519.315 seconds (3.174 MB/sec).
    8/3/2010 6:08:04 PM: SQL Backup process ended.
    Doug Tucker
    Database Administrator / Software Engineer
    Nelnet Business Solutions - FACTS-SIS
  • I have encountered a similar issue with 6.4.0.1013 - which I am using to fix the LATEST_ALL skipped log file bug with 6.4.0.56.

    The 1013 release seems to slow down more as a restore job goes on. I did several restores today. The first was not too bad, but the second was much slower and I had to cancel the 3rd after 4 hours for a 9GB database. I ran the restore on that same 9GB database using the .56 command line version and it completed in 11 minutes. Both were from a network backup file.

    I noticed the same performance problem when testing with 6.4.0.1001, but I do not have any saved data to back that up.

    Below are some tests done using .1013 vs .56 on the same database, same server, same backup files, this time from a local file location. The SQL server was not doing anything else at the time. The test server here is rather old and slow, but still... I did notice that .56 seems to maintain a higher, average CPU utilization than the slower restores with .1013.

    Test data:
    - Database size: 3.5GB
    - All backups created on production server using SQLBackup 6.4.0.56
    - compression level 4, 256-bit encryption, 3 backup threads
    - backups copied locally to the test server for these restore attempts, separate physical disk from SQL disks.

    SQL Backup log file 6.4.0.1013

    -SQL "restore database [DBName] from disk='c:\Temp\[SeverName]_[DBName]_20100803_*.sqb' LATEST_ALL with password='XXXXXXXXXX', REPLACE, DISCONNECT_EXISTING, RECOVERY, LOGTO = 'C:\Bin\SQLBackup_[DBName]FullRestore.SQL1.1013.log', mailto='mikeg@archipelago.ca' "

    PROCESSES COMPLETED SUCCESSFULLY

    03/08/2010 18:41:41: Restoring [DBName] (database) from:
    03/08/2010 18:41:41: c:\Temp\[SeverName]_[DBName]_20100803_070934_FULL.sqb

    03/08/2010 18:41:42: ALTER DATABASE [DBName] SET ONLINE RESTORE DATABASE [DBName] FROM VIRTUAL_DEVICE = 'SQLBACKUP_EFDF9783-3F78-4D75-901B-DBE17941BCBF', VIRTUAL_DEVICE = 'SQLBACKUP_EFDF9783-3F78-4D75-901B-DBE17941BCBF01', VIRTUAL_DEVICE = 'SQLBACKUP_EFDF9783-3F78-4D75-901B-DBE17941BCBF02' WITH BUFFERCOUNT = 18, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576 , NORECOVERY, REPLACE

    03/08/2010 18:44:58: Processed 186736 pages for database '[DBName]', file '[DBName]_Data' on file 1.
    03/08/2010 18:44:58: Processed 2 pages for database '[DBName]', file '[DBName]_log' on file 1.
    03/08/2010 18:44:58: RESTORE DATABASE successfully processed 186738 pages in 173.308 seconds (8.826 MB/sec).

    03/08/2010 18:44:58: Restoring [DBName] (transaction logs) from:
    03/08/2010 18:44:58: c:\Temp\[SeverName]_[DBName]_20100803_074115_LOG.sqb

    03/08/2010 18:44:58: RESTORE LOG [DBName] FROM VIRTUAL_DEVICE = 'SQLBACKUP_138BE1AD-A187-4F6E-AEDF-788229F19C91', VIRTUAL_DEVICE = 'SQLBACKUP_138BE1AD-A187-4F6E-AEDF-788229F19C9101', VIRTUAL_DEVICE = 'SQLBACKUP_138BE1AD-A187-4F6E-AEDF-788229F19C9102' WITH BUFFERCOUNT = 18, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576 , NORECOVERY, REPLACE

    03/08/2010 18:47:18: Processed 0 pages for database '[DBName]', file '[DBName]_Data' on file 1.
    03/08/2010 18:47:18: Processed 13836 pages for database '[DBName]', file '[DBName]_log' on file 1.
    03/08/2010 18:47:18: RESTORE LOG successfully processed 13836 pages in 81.170 seconds (1.396 MB/sec).

    03/08/2010 18:47:18: Restoring [DBName] (transaction logs) from:
    03/08/2010 18:47:18: c:\Temp\[SeverName]_[DBName]_20100803_103826_LOG.sqb

    03/08/2010 18:47:18: RESTORE LOG [DBName] FROM VIRTUAL_DEVICE = 'SQLBACKUP_C2F3D067-D704-4C06-A488-FE5C482DE7E7', VIRTUAL_DEVICE = 'SQLBACKUP_C2F3D067-D704-4C06-A488-FE5C482DE7E701', VIRTUAL_DEVICE = 'SQLBACKUP_C2F3D067-D704-4C06-A488-FE5C482DE7E702' WITH BUFFERCOUNT = 18, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576 , NORECOVERY, REPLACE

    03/08/2010 19:10:40: Processed 0 pages for database '[DBName]', file '[DBName]_Data' on file 1.
    03/08/2010 19:10:40: Processed 41491 pages for database '[DBName]', file '[DBName]_log' on file 1.
    03/08/2010 19:10:40: RESTORE LOG successfully processed 41491 pages in 1329.247 seconds (0.255 MB/sec).

    03/08/2010 19:10:40: Restoring [DBName] (transaction logs) from:
    03/08/2010 19:10:40: c:\Temp\[SeverName]_[DBName]_20100803_133835_LOG.sqb

    03/08/2010 19:10:41: RESTORE LOG [DBName] FROM VIRTUAL_DEVICE = 'SQLBACKUP_D588B70C-8F50-483C-A786-236D9B2E520F', VIRTUAL_DEVICE = 'SQLBACKUP_D588B70C-8F50-483C-A786-236D9B2E520F01', VIRTUAL_DEVICE = 'SQLBACKUP_D588B70C-8F50-483C-A786-236D9B2E520F02' WITH BUFFERCOUNT = 18, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576 , RECOVERY, REPLACE

    03/08/2010 19:34:32: Processed 0 pages for database '[DBName]', file '[DBName]_Data' on file 1.
    03/08/2010 19:34:32: Processed 41654 pages for database '[DBName]', file '[DBName]_log' on file 1.
    03/08/2010 19:34:32: RESTORE LOG successfully processed 41654 pages in 1339.540 seconds (0.254 MB/sec).

    03/08/2010 19:34:32: SQL Backup process ended.

    SQL Backup log file 6.4.0.56

    -SQL "restore database [DBName] from disk='c:\Temp\[SeverName]_[DBName]_20100803_*FULL.sqb' with password='XXXXXXXXXX', REPLACE, DISCONNECT_EXISTING, NORECOVERY, LOGTO = 'C:\Bin\SQLBackup_[DBName]FullRestore.SQLData1.0056.log', mailto='mikeg@archipelago.ca' "

    PROCESSES COMPLETED SUCCESSFULLY

    03/08/2010 19:50:55: Restoring [DBName] (database) from:
    03/08/2010 19:50:55: c:\Temp\[SeverName]_[DBName]_20100803_070934_FULL.sqb

    03/08/2010 19:50:56: ALTER DATABASE [DBName] SET ONLINE RESTORE DATABASE [DBName] FROM VIRTUAL_DEVICE = 'SQLBACKUP_C67B88AD-63D6-47C4-B98A-87E93ABF92E7', VIRTUAL_DEVICE = 'SQLBACKUP_C67B88AD-63D6-47C4-B98A-87E93ABF92E701', VIRTUAL_DEVICE = 'SQLBACKUP_C67B88AD-63D6-47C4-B98A-87E93ABF92E702' WITH BUFFERCOUNT = 18, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576 , NORECOVERY, REPLACE

    03/08/2010 19:52:50: Processed 186736 pages for database '[DBName]', file '[DBName]_Data' on file 1.
    03/08/2010 19:52:50: Processed 2 pages for database '[DBName]', file '[DBName]_log' on file 1.
    03/08/2010 19:52:50: RESTORE DATABASE successfully processed 186738 pages in 97.681 seconds (15.660 MB/sec).
    03/08/2010 19:52:50: SQL Backup process ended.



    SQL Backup log file 6.4.0.56

    -SQL "restore log [DBName] from disk='c:\Temp\[SeverName]_[DBName]_20100803_*Log.sqb' with password='XXXXXXXXXX', REPLACE, DISCONNECT_EXISTING, RECOVERY, LOGTO = 'C:\Bin\SQLBackup_[DBName]FullRestore.SQLLog1.0056.log', mailto='mikeg@archipelago.ca' "

    PROCESSES COMPLETED SUCCESSFULLY

    03/08/2010 19:52:51: Restoring [DBName] (transaction logs) from:
    03/08/2010 19:52:51: c:\Temp\[SeverName]_[DBName]_20100803_074115_LOG.sqb

    03/08/2010 19:52:51: RESTORE LOG [DBName] FROM VIRTUAL_DEVICE = 'SQLBACKUP_4B539039-F257-422E-ADD0-29EC9A0545B8', VIRTUAL_DEVICE = 'SQLBACKUP_4B539039-F257-422E-ADD0-29EC9A0545B801', VIRTUAL_DEVICE = 'SQLBACKUP_4B539039-F257-422E-ADD0-29EC9A0545B802' WITH BUFFERCOUNT = 18, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576 , NORECOVERY, REPLACE

    03/08/2010 19:53:11: Processed 0 pages for database '[DBName]', file '[DBName]_Data' on file 1.
    03/08/2010 19:53:11: Processed 13836 pages for database '[DBName]', file '[DBName]_log' on file 1.
    03/08/2010 19:53:11: RESTORE LOG successfully processed 13836 pages in 3.361 seconds (33.723 MB/sec).

    03/08/2010 19:53:11: Restoring [DBName] (transaction logs) from:
    03/08/2010 19:53:11: c:\Temp\[SeverName]_[DBName]_20100803_103826_LOG.sqb

    03/08/2010 19:53:11: RESTORE LOG [DBName] FROM VIRTUAL_DEVICE = 'SQLBACKUP_68BCDA9E-32BE-40E0-8593-B71A9ADE2D04', VIRTUAL_DEVICE = 'SQLBACKUP_68BCDA9E-32BE-40E0-8593-B71A9ADE2D0401', VIRTUAL_DEVICE = 'SQLBACKUP_68BCDA9E-32BE-40E0-8593-B71A9ADE2D0402' WITH BUFFERCOUNT = 18, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576 , NORECOVERY, REPLACE

    03/08/2010 19:53:53: Processed 0 pages for database '[DBName]', file '[DBName]_Data' on file 1.
    03/08/2010 19:53:53: Processed 41491 pages for database '[DBName]', file '[DBName]_log' on file 1.
    03/08/2010 19:53:53: RESTORE LOG successfully processed 41491 pages in 10.221 seconds (33.254 MB/sec).

    03/08/2010 19:53:53: Restoring [DBName] (transaction logs) from:
    03/08/2010 19:53:53: c:\Temp\[SeverName]_[DBName]_20100803_133835_LOG.sqb

    03/08/2010 19:53:54: RESTORE LOG [DBName] FROM VIRTUAL_DEVICE = 'SQLBACKUP_BEFCB8D8-7358-4A88-AF49-91D7555EAABD', VIRTUAL_DEVICE = 'SQLBACKUP_BEFCB8D8-7358-4A88-AF49-91D7555EAABD01', VIRTUAL_DEVICE = 'SQLBACKUP_BEFCB8D8-7358-4A88-AF49-91D7555EAABD02' WITH BUFFERCOUNT = 18, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576 , RECOVERY, REPLACE

    03/08/2010 19:54:56: Processed 0 pages for database '[DBName]', file '[DBName]_Data' on file 1.
    03/08/2010 19:54:56: Processed 41654 pages for database '[DBName]', file '[DBName]_log' on file 1.
    03/08/2010 19:54:56: RESTORE LOG successfully processed 41654 pages in 10.534 seconds (32.392 MB/sec).

    03/08/2010 19:54:56: SQL Backup process ended.
  • peteypetey Posts: 2,358 New member
    When you were restoring using 6.4.0.1013, were you using the SQL Backup Agent service, or the command line interface?

    Thanks.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
  • peteypetey Posts: 2,358 New member
    My apologies, build 1013 contained some debugging information left over from a support call I was working on.

    Please download patch 1014 here:

    ftp://support.red-gate.com/Patches/sql_ ... 0_1014.zip

    Also, you will find a file named 'readerlog_xxxx.txt' in your SQL Backup installation folder. You can delete this file.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
  • brosatobrosato Posts: 89 Bronze 2
    I can't seem to get restores to finish either. I'm calling the extended procedure.
  • I have now tested release 6.4.0.1014 as per the download posted above. I am happy to say that the restore speed is now back up to that of 6.4.0.56 AND the LATEST_ALL disk option also works, including from a network folder with many backup files (Full, Diff and Log) per database.

    Testing results are posted below, both for the extended stored procedure and the command line methods. These are on the same database as per my testing with .1013 posted above, but with a differential backup and newer log files included in the mix.

    Cheers!
    Testing results:


    Test Restore using SQLBackup 6.4.0.1014 extended stored procedure from network source backup files:

    -SQL "restore database [Database] FROM DISK='\\[FileServer]\[FileShare]\[SQLServer]_[Database]*.sqb' LATEST_ALL WITH password='XXXXXXXXXX', replace,

    disconnect_existing"

    PROCESSES COMPLETED SUCCESSFULLY

    04/08/2010 15:42:37: Restoring [Database] (database) from:
    04/08/2010 15:42:37: \\[FileServer]\[FileShare]\[SQLServer]_[Database]_20100803_070934_FULL.sqb

    04/08/2010 15:42:38: ALTER DATABASE [Database] SET ONLINE RESTORE DATABASE [Database] FROM VIRTUAL_DEVICE =

    'SQLBACKUP_35C8664A-A3D8-4C43-8D06-D6D2446B1584', VIRTUAL_DEVICE = 'SQLBACKUP_35C8664A-A3D8-4C43-8D06-D6D2446B158401', VIRTUAL_DEVICE =

    'SQLBACKUP_35C8664A-A3D8-4C43-8D06-D6D2446B158402' WITH BUFFERCOUNT = 18, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576 , NORECOVERY, REPLACE

    04/08/2010 15:44:33: Processed 186736 pages for database '[Database]', file '[Database]_Data' on file 1.
    04/08/2010 15:44:33: Processed 2 pages for database '[Database]', file '[Database]_log' on file 1.
    04/08/2010 15:44:33: RESTORE DATABASE successfully processed 186738 pages in 98.458 seconds (15.537 MB/sec).

    04/08/2010 15:44:33: Restoring [Database] (database) from:
    04/08/2010 15:44:33: \\[FileServer]\[FileShare]\[SQLServer]_[Database]_20100804_022321_DIFF.sqb

    04/08/2010 15:44:34: RESTORE DATABASE [Database] FROM VIRTUAL_DEVICE = 'SQLBACKUP_AD89F797-AFE1-4F75-8994-3A464CC816BE', VIRTUAL_DEVICE =

    'SQLBACKUP_AD89F797-AFE1-4F75-8994-3A464CC816BE01', VIRTUAL_DEVICE = 'SQLBACKUP_AD89F797-AFE1-4F75-8994-3A464CC816BE02' WITH BUFFERCOUNT = 18, BLOCKSIZE =

    65536, MAXTRANSFERSIZE = 1048576 , NORECOVERY, REPLACE

    04/08/2010 15:45:50: Processed 11536 pages for database '[Database]', file '[Database]_Data' on file 1.
    04/08/2010 15:45:50: Processed 1 pages for database '[Database]', file '[Database]_log' on file 1.
    04/08/2010 15:45:50: RESTORE DATABASE successfully processed 11537 pages in 60.255 seconds (1.568 MB/sec).

    04/08/2010 15:45:50: Restoring [Database] (transaction logs) from:
    04/08/2010 15:45:50: \\[FileServer]\[FileShare]\[SQLServer]_[Database]_20100804_073856_LOG.sqb

    04/08/2010 15:45:51: RESTORE LOG [Database] FROM VIRTUAL_DEVICE = 'SQLBACKUP_9B22178B-41BA-4BDE-8641-6802D9E94CF1', VIRTUAL_DEVICE =

    'SQLBACKUP_9B22178B-41BA-4BDE-8641-6802D9E94CF101', VIRTUAL_DEVICE = 'SQLBACKUP_9B22178B-41BA-4BDE-8641-6802D9E94CF102' WITH BUFFERCOUNT = 18, BLOCKSIZE =

    65536, MAXTRANSFERSIZE = 1048576 , NORECOVERY, REPLACE

    04/08/2010 15:46:15: Processed 0 pages for database '[Database]', file '[Database]_Data' on file 1.
    04/08/2010 15:46:15: Processed 13974 pages for database '[Database]', file '[Database]_log' on file 1.
    04/08/2010 15:46:15: RESTORE LOG successfully processed 13974 pages in 4.989 seconds (22.944 MB/sec).

    04/08/2010 15:46:15: Restoring [Database] (transaction logs) from:
    04/08/2010 15:46:15: \\[FileServer]\[FileShare]\[SQLServer]_[Database]_20100804_103835_LOG.sqb

    04/08/2010 15:46:15: RESTORE LOG [Database] FROM VIRTUAL_DEVICE = 'SQLBACKUP_50E44D3E-F8A5-4A73-9882-FE233EC3365F', VIRTUAL_DEVICE =

    'SQLBACKUP_50E44D3E-F8A5-4A73-9882-FE233EC3365F01', VIRTUAL_DEVICE = 'SQLBACKUP_50E44D3E-F8A5-4A73-9882-FE233EC3365F02' WITH BUFFERCOUNT = 18, BLOCKSIZE =

    65536, MAXTRANSFERSIZE = 1048576 , NORECOVERY, REPLACE

    04/08/2010 15:47:04: Processed 0 pages for database '[Database]', file '[Database]_Data' on file 1.
    04/08/2010 15:47:04: Processed 41932 pages for database '[Database]', file '[Database]_log' on file 1.
    04/08/2010 15:47:04: RESTORE LOG successfully processed 41932 pages in 16.261 seconds (21.124 MB/sec).

    04/08/2010 15:47:04: Restoring [Database] (transaction logs) from:
    04/08/2010 15:47:04: \\[FileServer]\[FileShare]\[SQLServer]_[Database]_20100804_134115_LOG.sqb

    04/08/2010 15:47:04: RESTORE LOG [Database] FROM VIRTUAL_DEVICE = 'SQLBACKUP_BBCE8E8A-834D-4E9E-9DE7-55A5D3E02000', VIRTUAL_DEVICE =

    'SQLBACKUP_BBCE8E8A-834D-4E9E-9DE7-55A5D3E0200001', VIRTUAL_DEVICE = 'SQLBACKUP_BBCE8E8A-834D-4E9E-9DE7-55A5D3E0200002' WITH BUFFERCOUNT = 18, BLOCKSIZE =

    65536, MAXTRANSFERSIZE = 1048576 , NORECOVERY, REPLACE

    04/08/2010 15:47:55: Processed 0 pages for database '[Database]', file '[Database]_Data' on file 1.
    04/08/2010 15:47:55: Processed 42036 pages for database '[Database]', file '[Database]_log' on file 1.
    04/08/2010 15:47:55: RESTORE LOG successfully processed 42036 pages in 19.833 seconds (17.362 MB/sec).

    04/08/2010 15:47:55: Restoring [Database] (transaction logs) from:
    04/08/2010 15:47:55: \\[FileServer]\[FileShare]\[SQLServer]_[Database]_20100804_153922_LOG.sqb

    04/08/2010 15:47:55: RESTORE LOG [Database] FROM VIRTUAL_DEVICE = 'SQLBACKUP_877033F0-2E6E-412C-AA9A-FD63DC92047C', VIRTUAL_DEVICE =

    'SQLBACKUP_877033F0-2E6E-412C-AA9A-FD63DC92047C01', VIRTUAL_DEVICE = 'SQLBACKUP_877033F0-2E6E-412C-AA9A-FD63DC92047C02' WITH BUFFERCOUNT = 18, BLOCKSIZE =

    65536, MAXTRANSFERSIZE = 1048576 , RECOVERY, REPLACE

    04/08/2010 15:48:46: Processed 0 pages for database '[Database]', file '[Database]_Data' on file 1.
    04/08/2010 15:48:46: Processed 28205 pages for database '[Database]', file '[Database]_log' on file 1.
    04/08/2010 15:48:46: RESTORE LOG successfully processed 28205 pages in 6.942 seconds (33.282 MB/sec).

    04/08/2010 15:48:46: SQL Backup process ended.



    TEST SCRIPT to compare performance of .1014 vs .56 via Command Line. Same database as above.

    SQLBackupC.6.4.0.56.exe -SQL "restore database [Database] from disk='c:\Temp\[SQLServer]_[Database]_20100803_070934_FULL.sqb' with password='XXXXXXXXXX',

    REPLACE, DISCONNECT_EXISTING, NORECOVERY, LOGTO = 'C:\Bin\SQLBackup_[Database]Restore.1.0056.log'"
    SQLBackupC.6.4.0.56.exe -SQL "restore database [Database] from disk='c:\Temp\[SQLServer]_[Database]_20100804_022321_DIFF.sqb' with password='XXXXXXXXXX',

    NORECOVERY, LOGTO = 'C:\Bin\SQLBackup_[Database]Restore.2.0056.log'"
    SQLBackupC.6.4.0.56.exe -SQL "restore LOG [Database] from disk='c:\Temp\[SQLServer]_[Database]_20100804_*_LOG.sqb' with password='XXXXXXXXXX', RECOVERY,

    LOGTO = 'C:\Bin\SQLBackup_[Database]Restore.3.0056.log'"

    SQLBackupC.6.4.0.1014.exe -SQL "restore database [Database] from disk='c:\Temp\[SQLServer]_[Database]_*.sqb' LATEST_ALL with password='XXXXXXXXXX',

    REPLACE, DISCONNECT_EXISTING, LOGTO = 'C:\Bin\SQLBackup_[Database]Restore.1.1014.log'"


    Results from test script:


    SQL Backup log file 6.4.0.56

    (command line)
    -SQL "restore database [Database] from disk='c:\Temp\[SQLServer]_[Database]_20100803_070934_FULL.sqb' with password='XXXXXXXXXX', REPLACE,

    DISCONNECT_EXISTING, NORECOVERY, LOGTO = 'C:\Bin\SQLBackup_[Database]Restore.1.0056.log'"

    PROCESSES COMPLETED SUCCESSFULLY

    04/08/2010 16:04:35: Restoring [Database] (database) from:
    04/08/2010 16:04:35: c:\Temp\[SQLServer]_[Database]_20100803_070934_FULL.sqb

    04/08/2010 16:04:39: ALTER DATABASE [Database] SET ONLINE RESTORE DATABASE [Database] FROM VIRTUAL_DEVICE =

    'SQLBACKUP_2BB89EA4-F01A-4E21-BB94-EE70B056604F', VIRTUAL_DEVICE = 'SQLBACKUP_2BB89EA4-F01A-4E21-BB94-EE70B056604F01', VIRTUAL_DEVICE =

    'SQLBACKUP_2BB89EA4-F01A-4E21-BB94-EE70B056604F02' WITH BUFFERCOUNT = 18, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576 , NORECOVERY, REPLACE

    04/08/2010 16:06:36: Processed 186736 pages for database '[Database]', file '[Database]_Data' on file 1.
    04/08/2010 16:06:36: Processed 2 pages for database '[Database]', file '[Database]_log' on file 1.
    04/08/2010 16:06:36: RESTORE DATABASE successfully processed 186738 pages in 98.119 seconds (15.590 MB/sec).
    04/08/2010 16:06:36: SQL Backup process ended.

    SQL Backup log file 6.4.0.56

    (command line)
    -SQL "restore database [Database] from disk='c:\Temp\[SQLServer]_[Database]_20100804_022321_DIFF.sqb' with password='XXXXXXXXXX', NORECOVERY, LOGTO =

    'C:\Bin\SQLBackup_[Database]Restore.2.0056.log'"

    PROCESSES COMPLETED SUCCESSFULLY

    04/08/2010 16:06:37: Restoring [Database] (database) from:
    04/08/2010 16:06:37: c:\Temp\[SQLServer]_[Database]_20100804_022321_DIFF.sqb

    04/08/2010 16:06:40: RESTORE DATABASE [Database] FROM VIRTUAL_DEVICE = 'SQLBACKUP_CA11A2B4-8737-4F23-940B-896137A745D2', VIRTUAL_DEVICE =

    'SQLBACKUP_CA11A2B4-8737-4F23-940B-896137A745D201', VIRTUAL_DEVICE = 'SQLBACKUP_CA11A2B4-8737-4F23-940B-896137A745D202' WITH BUFFERCOUNT = 18, BLOCKSIZE =

    65536, MAXTRANSFERSIZE = 1048576 , NORECOVERY

    04/08/2010 16:07:55: Processed 11536 pages for database '[Database]', file '[Database]_Data' on file 1.
    04/08/2010 16:07:55: Processed 1 pages for database '[Database]', file '[Database]_log' on file 1.
    04/08/2010 16:07:55: RESTORE DATABASE successfully processed 11537 pages in 60.554 seconds (1.560 MB/sec).
    04/08/2010 16:07:55: SQL Backup process ended.

    SQL Backup log file 6.4.0.56

    (command line)
    -SQL "restore LOG [Database] from disk='c:\Temp\[SQLServer]_[Database]_20100804_*_LOG.sqb' with password='XXXXXXXXXX', RECOVERY, LOGTO =

    'C:\Bin\SQLBackup_[Database]Restore.3.0056.log'"

    PROCESSES COMPLETED SUCCESSFULLY

    04/08/2010 16:08:04: Processing log group 210471245 ...
    04/08/2010 16:08:04: c:\Temp\[SQLServer]_[Database]_20100804_073856_LOG.sqb
    04/08/2010 16:08:04: Restoring [Database] (transaction logs) from:
    04/08/2010 16:08:04: c:\Temp\[SQLServer]_[Database]_20100804_073856_LOG.sqb

    04/08/2010 16:08:07: RESTORE LOG [Database] FROM VIRTUAL_DEVICE = 'SQLBACKUP_A21D4DE8-6800-4BBC-9F2A-0497674C1158', VIRTUAL_DEVICE =

    'SQLBACKUP_A21D4DE8-6800-4BBC-9F2A-0497674C115801', VIRTUAL_DEVICE = 'SQLBACKUP_A21D4DE8-6800-4BBC-9F2A-0497674C115802' WITH BUFFERCOUNT = 18, BLOCKSIZE =

    65536, MAXTRANSFERSIZE = 1048576 , NORECOVERY

    04/08/2010 16:08:29: Processed 0 pages for database '[Database]', file '[Database]_Data' on file 1.
    04/08/2010 16:08:29: Processed 13974 pages for database '[Database]', file '[Database]_log' on file 1.
    04/08/2010 16:08:29: RESTORE LOG successfully processed 13974 pages in 3.178 seconds (36.019 MB/sec).

    04/08/2010 16:08:29: Processing log group 165162333 ...
    04/08/2010 16:08:29: c:\Temp\[SQLServer]_[Database]_20100804_103835_LOG.sqb
    04/08/2010 16:08:29: Restoring [Database] (transaction logs) from:
    04/08/2010 16:08:29: c:\Temp\[SQLServer]_[Database]_20100804_103835_LOG.sqb

    04/08/2010 16:08:32: RESTORE LOG [Database] FROM VIRTUAL_DEVICE = 'SQLBACKUP_C3EF94BB-6314-44A6-BE54-B37A3AD09A24', VIRTUAL_DEVICE =

    'SQLBACKUP_C3EF94BB-6314-44A6-BE54-B37A3AD09A2401', VIRTUAL_DEVICE = 'SQLBACKUP_C3EF94BB-6314-44A6-BE54-B37A3AD09A2402' WITH BUFFERCOUNT = 18, BLOCKSIZE =

    65536, MAXTRANSFERSIZE = 1048576 , NORECOVERY

    04/08/2010 16:09:14: Processed 0 pages for database '[Database]', file '[Database]_Data' on file 1.
    04/08/2010 16:09:14: Processed 41932 pages for database '[Database]', file '[Database]_log' on file 1.
    04/08/2010 16:09:14: RESTORE LOG successfully processed 41932 pages in 9.984 seconds (34.405 MB/sec).

    04/08/2010 16:09:15: Processing log group 133458397 ...
    04/08/2010 16:09:15: c:\Temp\[SQLServer]_[Database]_20100804_134115_LOG.sqb
    04/08/2010 16:09:15: Restoring [Database] (transaction logs) from:
    04/08/2010 16:09:15: c:\Temp\[SQLServer]_[Database]_20100804_134115_LOG.sqb

    04/08/2010 16:09:18: RESTORE LOG [Database] FROM VIRTUAL_DEVICE = 'SQLBACKUP_C3456961-FB03-4E83-A77B-455C43DD2F0D', VIRTUAL_DEVICE =

    'SQLBACKUP_C3456961-FB03-4E83-A77B-455C43DD2F0D01', VIRTUAL_DEVICE = 'SQLBACKUP_C3456961-FB03-4E83-A77B-455C43DD2F0D02' WITH BUFFERCOUNT = 18, BLOCKSIZE =

    65536, MAXTRANSFERSIZE = 1048576 , NORECOVERY

    04/08/2010 16:09:55: Processed 0 pages for database '[Database]', file '[Database]_Data' on file 1.
    04/08/2010 16:09:55: Processed 42036 pages for database '[Database]', file '[Database]_log' on file 1.
    04/08/2010 16:09:55: RESTORE LOG successfully processed 42036 pages in 9.835 seconds (35.013 MB/sec).

    04/08/2010 16:09:55: Processing log group 206690717 ...
    04/08/2010 16:09:55: c:\Temp\[SQLServer]_[Database]_20100804_153922_LOG.sqb
    04/08/2010 16:09:55: Restoring [Database] (transaction logs) from:
    04/08/2010 16:09:55: c:\Temp\[SQLServer]_[Database]_20100804_153922_LOG.sqb

    04/08/2010 16:09:58: RESTORE LOG [Database] FROM VIRTUAL_DEVICE = 'SQLBACKUP_5B6310D2-2A0F-4271-BC25-1198A29C3BEC', VIRTUAL_DEVICE =

    'SQLBACKUP_5B6310D2-2A0F-4271-BC25-1198A29C3BEC01', VIRTUAL_DEVICE = 'SQLBACKUP_5B6310D2-2A0F-4271-BC25-1198A29C3BEC02' WITH BUFFERCOUNT = 18, BLOCKSIZE =

    65536, MAXTRANSFERSIZE = 1048576 , RECOVERY

    04/08/2010 16:11:20: Processed 0 pages for database '[Database]', file '[Database]_Data' on file 1.
    04/08/2010 16:11:20: Processed 28205 pages for database '[Database]', file '[Database]_log' on file 1.
    04/08/2010 16:11:20: RESTORE LOG successfully processed 28205 pages in 6.691 seconds (34.531 MB/sec).

    04/08/2010 16:11:20: SQL Backup process ended.



    SQL Backup log file 6.4.0.1014

    (command line)
    -SQL "restore database [Database] from disk='c:\Temp\[SQLServer]_[Database]_*.sqb' LATEST_ALL with password='XXXXXXXXXX', REPLACE, DISCONNECT_EXISTING,

    LOGTO = 'C:\Bin\SQLBackup_[Database]Restore.1.1014.log'"

    PROCESSES COMPLETED SUCCESSFULLY

    04/08/2010 16:11:51: Restoring [Database] (database) from:
    04/08/2010 16:11:51: c:\Temp\[SQLServer]_[Database]_20100803_070934_FULL.sqb

    04/08/2010 16:11:55: ALTER DATABASE [Database] SET ONLINE RESTORE DATABASE [Database] FROM VIRTUAL_DEVICE =

    'SQLBACKUP_D51ECAD6-FBF8-4053-829A-20DABF4BF823', VIRTUAL_DEVICE = 'SQLBACKUP_D51ECAD6-FBF8-4053-829A-20DABF4BF82301', VIRTUAL_DEVICE =

    'SQLBACKUP_D51ECAD6-FBF8-4053-829A-20DABF4BF82302' WITH BUFFERCOUNT = 18, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576 , NORECOVERY, REPLACE

    04/08/2010 16:14:12: Processed 186736 pages for database '[Database]', file '[Database]_Data' on file 1.
    04/08/2010 16:14:12: Processed 2 pages for database '[Database]', file '[Database]_log' on file 1.
    04/08/2010 16:14:12: RESTORE DATABASE successfully processed 186738 pages in 100.350 seconds (15.244 MB/sec).

    04/08/2010 16:14:12: Restoring [Database] (database) from:
    04/08/2010 16:14:12: c:\Temp\[SQLServer]_[Database]_20100804_022321_DIFF.sqb

    04/08/2010 16:14:15: RESTORE DATABASE [Database] FROM VIRTUAL_DEVICE = 'SQLBACKUP_A9D33290-6282-4462-ADB7-B550595F3E7A', VIRTUAL_DEVICE =

    'SQLBACKUP_A9D33290-6282-4462-ADB7-B550595F3E7A01', VIRTUAL_DEVICE = 'SQLBACKUP_A9D33290-6282-4462-ADB7-B550595F3E7A02' WITH BUFFERCOUNT = 18, BLOCKSIZE =

    65536, MAXTRANSFERSIZE = 1048576 , NORECOVERY, REPLACE

    04/08/2010 16:15:45: Processed 11536 pages for database '[Database]', file '[Database]_Data' on file 1.
    04/08/2010 16:15:45: Processed 1 pages for database '[Database]', file '[Database]_log' on file 1.
    04/08/2010 16:15:45: RESTORE DATABASE successfully processed 11537 pages in 61.936 seconds (1.525 MB/sec).

    04/08/2010 16:15:54: Processing log group 210471245 ...
    04/08/2010 16:15:54: c:\Temp\[SQLServer]_[Database]_20100804_073856_LOG.sqb
    04/08/2010 16:15:54: Restoring [Database] (transaction logs) from:
    04/08/2010 16:15:54: c:\Temp\[SQLServer]_[Database]_20100804_073856_LOG.sqb

    04/08/2010 16:15:57: RESTORE LOG [Database] FROM VIRTUAL_DEVICE = 'SQLBACKUP_58885327-13A2-4212-99F1-8908FFA34B40', VIRTUAL_DEVICE =

    'SQLBACKUP_58885327-13A2-4212-99F1-8908FFA34B4001', VIRTUAL_DEVICE = 'SQLBACKUP_58885327-13A2-4212-99F1-8908FFA34B4002' WITH BUFFERCOUNT = 18, BLOCKSIZE =

    65536, MAXTRANSFERSIZE = 1048576 , NORECOVERY, REPLACE

    04/08/2010 16:16:31: Processed 0 pages for database '[Database]', file '[Database]_Data' on file 1.
    04/08/2010 16:16:31: Processed 13974 pages for database '[Database]', file '[Database]_log' on file 1.
    04/08/2010 16:16:31: RESTORE LOG successfully processed 13974 pages in 3.447 seconds (33.208 MB/sec).

    04/08/2010 16:16:31: Processing log group 165162333 ...
    04/08/2010 16:16:31: c:\Temp\[SQLServer]_[Database]_20100804_103835_LOG.sqb
    04/08/2010 16:16:31: Restoring [Database] (transaction logs) from:
    04/08/2010 16:16:31: c:\Temp\[SQLServer]_[Database]_20100804_103835_LOG.sqb

    04/08/2010 16:16:34: RESTORE LOG [Database] FROM VIRTUAL_DEVICE = 'SQLBACKUP_40954DD7-57DD-434D-B7CB-8D038C843D6D', VIRTUAL_DEVICE =

    'SQLBACKUP_40954DD7-57DD-434D-B7CB-8D038C843D6D01', VIRTUAL_DEVICE = 'SQLBACKUP_40954DD7-57DD-434D-B7CB-8D038C843D6D02' WITH BUFFERCOUNT = 18, BLOCKSIZE =

    65536, MAXTRANSFERSIZE = 1048576 , NORECOVERY, REPLACE

    04/08/2010 16:17:51: Processed 0 pages for database '[Database]', file '[Database]_Data' on file 1.
    04/08/2010 16:17:51: Processed 41932 pages for database '[Database]', file '[Database]_log' on file 1.
    04/08/2010 16:17:51: RESTORE LOG successfully processed 41932 pages in 10.607 seconds (32.384 MB/sec).

    04/08/2010 16:17:51: Processing log group 133458397 ...
    04/08/2010 16:17:51: c:\Temp\[SQLServer]_[Database]_20100804_134115_LOG.sqb
    04/08/2010 16:17:51: Restoring [Database] (transaction logs) from:
    04/08/2010 16:17:51: c:\Temp\[SQLServer]_[Database]_20100804_134115_LOG.sqb

    04/08/2010 16:17:54: RESTORE LOG [Database] FROM VIRTUAL_DEVICE = 'SQLBACKUP_BC97D72C-E00F-4EB0-810C-141DED6AFE2D', VIRTUAL_DEVICE =

    'SQLBACKUP_BC97D72C-E00F-4EB0-810C-141DED6AFE2D01', VIRTUAL_DEVICE = 'SQLBACKUP_BC97D72C-E00F-4EB0-810C-141DED6AFE2D02' WITH BUFFERCOUNT = 18, BLOCKSIZE =

    65536, MAXTRANSFERSIZE = 1048576 , NORECOVERY, REPLACE

    04/08/2010 16:19:08: Processed 0 pages for database '[Database]', file '[Database]_Data' on file 1.
    04/08/2010 16:19:08: Processed 42036 pages for database '[Database]', file '[Database]_log' on file 1.
    04/08/2010 16:19:08: RESTORE LOG successfully processed 42036 pages in 10.443 seconds (32.975 MB/sec).

    04/08/2010 16:19:08: Processing log group 206690717 ...
    04/08/2010 16:19:08: c:\Temp\[SQLServer]_[Database]_20100804_153922_LOG.sqb
    04/08/2010 16:19:08: Restoring [Database] (transaction logs) from:
    04/08/2010 16:19:08: c:\Temp\[SQLServer]_[Database]_20100804_153922_LOG.sqb

    04/08/2010 16:19:11: RESTORE LOG [Database] FROM VIRTUAL_DEVICE = 'SQLBACKUP_25131E2A-EAF3-4B7A-BBF2-5746EE38942C', VIRTUAL_DEVICE =

    'SQLBACKUP_25131E2A-EAF3-4B7A-BBF2-5746EE38942C01', VIRTUAL_DEVICE = 'SQLBACKUP_25131E2A-EAF3-4B7A-BBF2-5746EE38942C02' WITH BUFFERCOUNT = 18, BLOCKSIZE =

    65536, MAXTRANSFERSIZE = 1048576 , RECOVERY, REPLACE

    04/08/2010 16:20:30: Processed 0 pages for database '[Database]', file '[Database]_Data' on file 1.
    04/08/2010 16:20:30: Processed 28205 pages for database '[Database]', file '[Database]_log' on file 1.
    04/08/2010 16:20:30: RESTORE LOG successfully processed 28205 pages in 6.781 seconds (34.072 MB/sec).

    04/08/2010 16:20:30: SQL Backup process ended.
  • peteypetey Posts: 2,358 New member
    Thanks for the detailed logs. Glad to hear the patch resolves the issue.

    One strange item is the restore throughput of the differential restore i.e. < 2 MB/sec. Seems to be consistent across all versions. I've never encountered a situation where the differential restore was so much slower than a full/log restore. Is the native SQL Server restore for a similar differential file just as slow?

    Thanks.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
  • brosatobrosato Posts: 89 Bronze 2
    I'm still plagued with problems. Here's the latest from the GUI
    SQLBackup. Crash!

    Object reference not set to an instance of an object.
    WorkerExecutionException

    at RedGate.SQLBackup.Engine.ConfigurableThreadPool.a(Exception )
    at RedGate.SQLBackup.Engine.ConfigurableThreadPool.a.b()
    at System.Threading.ThreadHelper.ThreadStart_Context(Object state)
    at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
    at System.Threading.ThreadHelper.ThreadStart()


    NullReferenceException

    Object reference not set to an instance of an object.

    at g.a(SqlConnection , aD )
    at g.b(Object )
  • Brian DonahueBrian Donahue Posts: 6,590 Bronze 1
    Hi,
    The UI is not petey's specialty, but when I translate the stack trace I think that the UI cannot update the file copy list table on the client-side. It could either be bad server-side data being replicated back or corruption in the client-side data store, if that helps.
  • Eddie DEddie D Posts: 1,780 Rose Gold 5
    Hi

    With regards to the GUI error with the WorkerExecutionException.

    Please try deleting the GUI cache components as follows:

    1. Close the SQL Backup GUI.
    2. Using Windows Explorer navigate
    to the following directory:

    Windows 2003 server / Windows XP
    C:\Documents and settings\<User_Name>\Application Data\Red Gate\SQL Backup\Server Data

    Windows 2008 server / Windows Vista / Windows 7
    C:\Users\<user_name\AppData\Local\Red Gate\SQL Backup\Server Data

    3. In the server Data folder you will find one or more .dat files, for example 1.dat, 2.dat, 8.dat localDataCache.dat.

    4. Delete all the files contained within the Server Data folder that have a .dat file extension so that the folder is empty.

    5. Now reopen the SQL Backup GUI, the .dat files deleted in the previous step will now be recreated and the reported problem resolved.

    I hope the above helps.

    Many Thanks
    Eddie
    Eddie Davis
    Senior Product Support Engineer
    Redgate Software Ltd
    Email: support@red-gate.com
  • Well, it appears that my testing was not sufficiently thorough. Release .1014 did resolve the slow restore speed on the smaller databases I used for the testing. However, on a larger database, it hangs up just as did .1001 and .1013.

    The database in question is about 30GB for the data file.
    Release 6.4.0.56 can restore this database on my test server in about 45 minutes. In the "In Progress" view of the UI, it reaches 27.3GB restored after about 18 minutes and stays there until the restore completes. With release .1013, the progress halted at 9.1GB restored and stayed there until I killed the job after several hours. With .1014, the reported progress reaches 27.3GB in about the same time as release .56, but then it never finishes either - at least not within the limits of my tolerance :) I saw this same behaviour with .1014 on this same DB when I tried to restore a very large log backup (after a rebuild of all indexes). The log backup size was 61GB compressed to 9GB (full DB backup was ~90GB). Note to self - enable frequent log backups during reindex next time! The log restore attempt with 6.4.0.1014 ran for over 24 hours before I canned it. I did not attempt that log restore with .56
  • RE the slow differential restore speed shown in my earlier post: I tried the differential restores again on that same database using new full and diff backups for 6.4.0.56, 6.4.0.1014 and native. I did not get results quite as slow this time, but the RedGate differential restores were less than one third the speed of the native restore - 1.58MB/s vs 5.28MB/s, while the full backups restored at 12 to 15MB/s. Restore log output is shown below.

    Restore comparison - native SQL vs 6.4.0.56 vs .1014:

    Test database - data file 1661MB, 324MB free; log file = 2GB, 97% free.

    Native backup restore:

    Native Full restore:
    Processed 186736 pages for database 'TestDB', file 'TestDB_Data' on file 1.
    Processed 2 pages for database 'TestDB', file 'TestDB_Log' on file 1.
    RESTORE DATABASE successfully processed 186738 pages in 112.014 seconds (13.656 MB/sec).

    Native Differential restore:
    Processed 43432 pages for database 'TestDB', file 'TestDB_Data' on file 2.
    Processed 3 pages for database 'TestDB', file 'TestDB_log' on file 2.
    RESTORE DATABASE successfully processed 43435 pages in 67.421 seconds (5.277 MB/sec).


    RedGate SQL Backup 6.4.0.56 restore:

    SQL Backup log file 6.4.0.56

    (command line)
    -SQL "restore database [TestDB] from disk='c:\Temp\TestDB_20100803_*_FULL.sqb' with password='XXXXXXXXXX', replace, disconnect_existing, norecovery, LOGTO = 'C:\Bin\SQLBackup_TestDB.Full.0056.log'"

    PROCESSES COMPLETED SUCCESSFULLY

    07/08/2010 09:04:32: Restoring TestDB (database) from:
    07/08/2010 09:04:32: c:\Temp\TestDB_20100803_070934_FULL.sqb

    07/08/2010 09:04:36: ALTER DATABASE [TestDB] SET ONLINE RESTORE DATABASE [TestDB] FROM VIRTUAL_DEVICE = 'SQLBACKUP_87DC88F8-053B-42E6-9D89-0EAA3E4D2DB6', VIRTUAL_DEVICE = 'SQLBACKUP_87DC88F8-053B-42E6-9D89-0EAA3E4D2DB601', VIRTUAL_DEVICE = 'SQLBACKUP_87DC88F8-053B-42E6-9D89-0EAA3E4D2DB602' WITH BUFFERCOUNT = 18, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576 , NORECOVERY, REPLACE

    07/08/2010 09:06:32: Processed 186736 pages for database 'TestDB', file 'TestDB_Data' on file 1.
    07/08/2010 09:06:32: Processed 2 pages for database 'TestDB', file 'TestDB_log' on file 1.
    07/08/2010 09:06:32: RESTORE DATABASE successfully processed 186738 pages in 97.580 seconds (15.676 MB/sec).
    07/08/2010 09:06:32: SQL Backup process ended.

    SQL Backup log file 6.4.0.56

    (command line)
    -SQL "restore database [TestDB] from disk='c:\Temp\TestDB_20100806_*_DIFF.sqb' with password='XXXXXXXXXX', recovery, LOGTO = 'C:\Bin\SQLBackup_TestDB.Diff.0056.log'"

    PROCESSES COMPLETED SUCCESSFULLY

    07/08/2010 09:06:33: Restoring TestDB (database) from:
    07/08/2010 09:06:33: c:\Temp\TestDB_20100806_032331_DIFF.sqb

    07/08/2010 09:06:36: RESTORE DATABASE [TestDB] FROM VIRTUAL_DEVICE = 'SQLBACKUP_0E811483-73E1-42AA-BA61-227937D4C03F', VIRTUAL_DEVICE = 'SQLBACKUP_0E811483-73E1-42AA-BA61-227937D4C03F01', VIRTUAL_DEVICE = 'SQLBACKUP_0E811483-73E1-42AA-BA61-227937D4C03F02' WITH BUFFERCOUNT = 18, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576 , RECOVERY

    07/08/2010 09:07:56: Processed 11664 pages for database 'TestDB', file 'TestDB_Data' on file 1.
    07/08/2010 09:07:56: Processed 1 pages for database 'TestDB', file 'TestDB_log' on file 1.
    07/08/2010 09:07:56: RESTORE DATABASE successfully processed 11665 pages in 60.416 seconds (1.581 MB/sec).
    07/08/2010 09:07:56: SQL Backup process ended.


    RedGate SQL Backup 6.4.0.1014 restore:


    SQL Backup log file 6.4.0.1014

    (command line)
    -SQL "restore database [TestDB] from disk='c:\Temp\TestDB_20100803_*_FULL.sqb' with password='XXXXXXXXXX', replace, disconnect_existing, norecovery, LOGTO = 'C:\Bin\SQLBackup_TestDB.Full.1014.log'"

    PROCESSES COMPLETED SUCCESSFULLY

    07/08/2010 08:53:27: Restoring TestDB (database) from:
    07/08/2010 08:53:27: c:\Temp\TestDB_20100803_070934_FULL.sqb

    07/08/2010 08:53:31: ALTER DATABASE [TestDB] SET ONLINE RESTORE DATABASE [TestDB] FROM VIRTUAL_DEVICE = 'SQLBACKUP_B9612B26-B07F-43AC-A877-A043D58FB5B9', VIRTUAL_DEVICE = 'SQLBACKUP_B9612B26-B07F-43AC-A877-A043D58FB5B901', VIRTUAL_DEVICE = 'SQLBACKUP_B9612B26-B07F-43AC-A877-A043D58FB5B902' WITH BUFFERCOUNT = 18, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576 , NORECOVERY, REPLACE

    07/08/2010 08:55:28: Processed 186736 pages for database 'TestDB', file 'TestDB_Data' on file 1.
    07/08/2010 08:55:28: Processed 2 pages for database 'TestDB', file 'TestDB_log' on file 1.
    07/08/2010 08:55:28: RESTORE DATABASE successfully processed 186738 pages in 98.510 seconds (15.528 MB/sec).
    07/08/2010 08:55:28: SQL Backup process ended.


    SQL Backup log file 6.4.0.1014

    (command line)
    -SQL "restore database [TestDB] from disk='c:\Temp\TestDB_20100806_*_DIFF.sqb' with password='XXXXXXXXXX', recovery, LOGTO = 'C:\Bin\SQLBackup_TestDB.Diff.1014.log'"

    PROCESSES COMPLETED SUCCESSFULLY

    07/08/2010 08:58:13: Restoring TestDB (database) from:
    07/08/2010 08:58:13: c:\Temp\TestDB_20100806_032331_DIFF.sqb

    07/08/2010 08:58:17: RESTORE DATABASE [TestDB] FROM VIRTUAL_DEVICE = 'SQLBACKUP_8B61A026-CC88-4D56-AC8A-E3E3F2F48111', VIRTUAL_DEVICE = 'SQLBACKUP_8B61A026-CC88-4D56-AC8A-E3E3F2F4811101', VIRTUAL_DEVICE = 'SQLBACKUP_8B61A026-CC88-4D56-AC8A-E3E3F2F4811102' WITH BUFFERCOUNT = 18, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576 , RECOVERY

    07/08/2010 08:59:36: Processed 11664 pages for database 'TestDB', file 'TestDB_Data' on file 1.
    07/08/2010 08:59:36: Processed 1 pages for database 'TestDB', file 'TestDB_log' on file 1.
    07/08/2010 08:59:36: RESTORE DATABASE successfully processed 11665 pages in 60.264 seconds (1.585 MB/sec).
    07/08/2010 08:59:36: SQL Backup process ended.
  • peteypetey Posts: 2,358 New member
    Thanks for running the tests.

    Even for a full restore, the SQL Backup times are significantly faster than the native restore. What is the compression rate on the SQL Backup backups (full and differential)? Are the backup files also located on the same drive as the database files? A low compression rate, and also running everything off the same physical drive, are 2 things that could result in a slower restore speed.

    Thanks.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
  • All of the Red Gate SQL backup files were compressed at level 4 using 3 threads and 256 bit encryption. The temp drive used to hold the backup files for the test restores was on a different local disk set from the SQL data/log files.
  • peteypetey Posts: 2,358 New member
    Thanks for the details. What was the compression rate for the full and differential backups? 50%? 80%?
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
  • The reported "Compressed By" amount was 97% for the full backup and 92% for the differential.

    Note: for me, the slower rate for the differential restore with SQL Backup is not really an issue. The faster restore over native backups is great - except in the instances with release 6.4.0.10xx where the larger restore jobs fail to complete. That is the more important issue from my perspective. 6.4.0.56 is working fine for my day to day use - I can get by without the functional LATEST_ALL option until the .10xx "patch" is really ready to go.

    Thanks for all your efforts!
  • peteypetey Posts: 2,358 New member
    except in the instances with release 6.4.0.10xx where the larger restore jobs fail to complete.
    Which post is that, or did you log an internal bug report with us?

    Thanks.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
  • It was my post in this thread dated 2010-08-07 09:20 Pacific Daylight Time.
    Post subject: Slow Restore "Fixed Congrats" premature
  • peteypetey Posts: 2,358 New member
    Sorry, I missed that post. Could you provide me the BACKUP command used to generate the backup file? I basically need to know the compression level used, if it was a split file backup or single file multi-thread backup etc.

    Thanks.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
  • All RedGate SQL Backup file in all my tests are production backups, all with the same settings from 6.4.0.56:
    single backup file, 3 threads, compression level 4, 256 bit encryption

    Full backup command:
    EXECUTE master..sqlbackup '-SQL "BACKUP DATABASES EXCLUDE [Databas list etc..] TO DISK = ''\\[network resource]\<AUTO>.sqb'' WITH ERASEFILES_ATSTART = 21, MAILTO = ''sql_alerts@archipelago.ca'', PASSWORD = ''<ENCRYPTEDPASSWORD>[pwd]=</ENCRYPTEDPASSWORD>'', DISKRETRYINTERVAL = 120, DISKRETRYCOUNT = 5, COMPRESSION = 4, INIT, KEYSIZE = 256, THREADCOUNT = 3, VERIFY"', @exitcode OUT, @sqlerrorcode OUT
  • peteypetey Posts: 2,358 New member
    I could not reproduce your error.

    I created a database with a 31.8 GB data file and a 672 MB log file. Using the same backup options as you, SQL Backup generated a backup file that was 7.22 GB in size. I could restore this backup without problems using SQL Backup 6.4.0.1014, using the extended stored procedure and the GUI. The backup file was created using 6.4.0.56 and also 6.4.0.1014.

    Could you please check if SQL Backup generated a stack trace when it appeared to hanged? This stack trace is stored in a file named SQBCoreService_<instance name>_bugreport.txt, and is located in 'C:\Documents and Settings\All Users\Application Data\Red Gate\SQL Backup\Log\' on Windows 2003 and older, and 'C:\ProgramData\Red Gate\SQL Backup\Log\' on Windows Vista and newer.

    Thanks.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
  • brosatobrosato Posts: 89 Bronze 2
    edited August 10, 2010 12:50PM
    I can't get differential restores to finish. They just hang once they get to a certain point.

    Actually, restores of full backups hang too.


    <edit>

    There must be something wrong with the latest build I'm using to fix the LATEST_ALL bug. Restores are hit or miss and it doesn't matter what the size is.
  • peteypetey Posts: 2,358 New member
    As per my last post, could you please check if SQL Backup generated a stack trace when it appeared to hanged? This stack trace is stored in a file named SQBCoreService_<instance name>_bugreport.txt, and is located in 'C:\Documents and Settings\All Users\Application Data\Red Gate\SQL Backup\Log\' on Windows 2003 and older, and 'C:\ProgramData\Red Gate\SQL Backup\Log\' on Windows Vista and newer.

    Also, how large is your backup file? Would it be possible/feasible to send us a copy?

    Thanks.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
  • brosatobrosato Posts: 89 Bronze 2
    petey wrote:
    As per my last post, could you please check if SQL Backup generated a stack trace when it appeared to hanged? This stack trace is stored in a file named SQBCoreService_<instance name>_bugreport.txt, and is located in 'C:\Documents and Settings\All Users\Application Data\Red Gate\SQL Backup\Log\' on Windows 2003 and older, and 'C:\ProgramData\Red Gate\SQL Backup\Log\' on Windows Vista and newer.

    Also, how large is your backup file? Would it be possible/feasible to send us a copy?

    Thanks.


    There is no file by that name in that directory. There are other log files. The backup file I'm trying to restore right now is 430MB. If I look in the GUI under the in progress tab, it processed up to 4.5GB and stopped. I just restored one that was twice that size but it took 5 times before it finished. I though it might be because the files were on a network share so I copied them local. Still doesn't work.

    This is our Great Plains database so I don't believe I can send it to you.
  • brosatobrosato Posts: 89 Bronze 2
    I just reverted back to 6.4.0.56 and the restore finished. Strangely enough, the processed size reported in the GUI was 4.5GB. So it seems the other one got to the end but would never finish.
  • OK, I managed to force error output from these "hung" restores - it matters in which order one kills the backup processes from SQL Activity Monitor (vs just restarting the SQL Backup service). There is no data in the _bugreport log file for these events, probably because I was just killing the process - it was not "crashing" per se. I found that if I use SQL Activity Monitor to kill the SQL process with the restore command, then the "lead" SQL process in the multi-thread restore chain (the one that shows the restore commands per virtual disk device in the details), I will get logged errors in the SQL Backup Output.

    I re-attempted my test server (6.4.0.1014) restore of the 30GB database using a fresh, production backup (6.4.0.56, 3 threads, level 4 compression, 256-bit, single file). I killed the restore after 6.5 hours. This time I did not remember to disable a regular log restore job before I initiated the test restore. The first stage of the log restore (different database) hung for the entire time the full restore was "working" and did not resume once I finally killed the full restore (these log restores typically complete in 30 to 50 seconds). As soon as I killed the hung log restore, the job that initiated it went on to its next DB and resumed restoring logs correctly. Below is the output from the error logs of both killed jobs.

    While these restores were hung up, the SQL activity monitor showed an additional SQBCoreService process per thread of the restore. The properties for these threads (details) were blank, but the CPU use column kept continuously cycling to 5 seconds for each process, while the top level processes - for the initial restore command executed in SSMS and the next level down that detailed the restore per virtual disk - had continuously increasing CPU counts.
    The top level process for the restore showed as Application="SQL Backup", Status="Runnable", Command="Execute", Wait Type= "MSQL_XP"

    The virtual disk detailed process listed as "SQBCoreService.exe", "Suspended", "Restore Database", wait type = "BACKUPTHREAD"

    The "cycling" processes showed as "SQBCoreService.exe", "Suspended", "Restore Database", wait type = "BACKUPIO".

    In the error output, each restore thread has an API timeout 1125 seconds after the start of the restore process. The log restore that was killed shows the same API timeout errors but only 650 seconds after the start entry for the restore process. The VDI timeout setting on this server is 900.

    Killed, Full restore log output:
    -SQL "RESTORE DATABASE [TestDB] FROM DISK = '\\[BackupShare]\ServerName_TestDB_20100810_021022_FULL.sqb' WITH MAILTO = '[alert email]', PASSWORD = 'XXXXXXXXXX', NORECOVERY, DISCONNECT_EXISTING, REPLACE "

    ERRORS AND WARNINGS


    10/08/2010 07:26:03: Restoring TestDB (database) from:
    10/08/2010 07:26:03: \\[BackupShare]\ServerName_TestDB_20100810_021022_FULL.sqb

    10/08/2010 07:26:03: ALTER DATABASE [TestDB] SET ONLINE RESTORE DATABASE [TestDB] FROM VIRTUAL_DEVICE = 'SQLBACKUP_CBAA31FF-C010-441D-A629-B6129EE428BF', VIRTUAL_DEVICE = 'SQLBACKUP_CBAA31FF-C010-441D-A629-B6129EE428BF01', VIRTUAL_DEVICE = 'SQLBACKUP_CBAA31FF-C010-441D-A629-B6129EE428BF02' WITH BUFFERCOUNT = 18, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576 , NORECOVERY, REPLACE

    10/08/2010 07:44:48: Thread 0 error:
    Process terminated unexpectedly. Error code: -2139684861 (The api was waiting and the timeout interval had elapsed.) 10/08/2010 07:44:48:
    10/08/2010 07:44:48: Thread 1 error:
    Process terminated unexpectedly. Error code: -2139684861 (The api was waiting and the timeout interval had elapsed.) 10/08/2010 07:44:48:
    10/08/2010 07:44:48: Thread 2 error:
    Process terminated unexpectedly. Error code: -2139684861 (The api was waiting and the timeout interval had elapsed.) 10/08/2010 07:44:48:
    10/08/2010 13:56:56: SQL error 3013: SQL error 3013: RESTORE DATABASE is terminating abnormally.
    10/08/2010 13:56:56: SQL error 3203: SQL error 3203: Read on "SQLBACKUP_CBAA31FF-C010-441D-A629-B6129EE428BF01" failed: 995(The I/O operation has been aborted because of either a thread exit or an application request.)

    Killed Log restore output:
    -SQL "RESTORE LOG [TestDB2] FROM DISK = '\\[BackupShare]\ServerName_TestDB2_*_LOG.sqb' WITH ERASEFILES = 14, FILEOPTIONS = 1, MAILTO_ONERRORONLY = '[Alert Email]', PASSWORD = 'XXXXXXXXXX', STANDBY = 'C:\[LocalWorkDir]\UNDO_TestDB2.dat', DISCONNECT_EXISTING, MOVETO = '\\[BackupShare]\LogShipped' "

    ERRORS AND WARNINGS


    10/08/2010 07:30:01: Restoring TestDB2 (transaction logs) from:
    10/08/2010 07:30:01: \\VirtualCenter\SQLBackup$\ServerName\ServerName_TestDB2_20100810_072500_LOG.sqb

    10/08/2010 07:30:01: ALTER DATABASE [TestDB2] SET ONLINE RESTORE LOG [TestDB2] FROM VIRTUAL_DEVICE = 'SQLBACKUP_906A5990-1291-4D39-9327-5EBACB5BFF7A', VIRTUAL_DEVICE = 'SQLBACKUP_906A5990-1291-4D39-9327-5EBACB5BFF7A01', VIRTUAL_DEVICE = 'SQLBACKUP_906A5990-1291-4D39-9327-5EBACB5BFF7A02' WITH BUFFERCOUNT = 18, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576 , STANDBY = N'C:[LocalWorkDir]\UNDO_TestDB2.dat'

    10/08/2010 07:40:51: Thread 0 error:
    Process terminated unexpectedly. Error code: -2139684861 (The api was waiting and the timeout interval had elapsed.) 10/08/2010 07:40:51:
    10/08/2010 07:40:51: Thread 1 error:
    Process terminated unexpectedly. Error code: -2139684861 (The api was waiting and the timeout interval had elapsed.) 10/08/2010 07:40:51:
    10/08/2010 07:40:51: Thread 2 error:
    Process terminated unexpectedly. Error code: -2139684861 (The api was waiting and the timeout interval had elapsed.) 10/08/2010 07:40:51:
    10/08/2010 14:00:17: SQL error 3013: SQL error 3013: RESTORE LOG is terminating abnormally.
  • After the 30GB full restore failure above with 6.4.0.1014, I reverted this test server to 6.4.0.56 and then re-ran the same restore command. It completed successfully in 00:46:37.
  • peteypetey Posts: 2,358 New member
    Could you please try build 6.4.0.1015 (ftp://support.red-gate.com/Patches/sql_ ... 0_1015.zip)? I've tried to remove all unnecessary debugging code from prior patches for this version.

    Thanks.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
Sign In or Register to comment.