restore time VERY slow (compared to native SQL restore)
dhtucker
Posts: 41 Bronze 3
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).
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
Database Administrator / Software Engineer
Nelnet Business Solutions - FACTS-SIS
Comments
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.
SQL Backup Consultant Developer
Associate, Yohz Software
Beyond compression - SQL Backup goodies under the hood, updated for version 8
Database Administrator / Software Engineer
Nelnet Business Solutions - FACTS-SIS
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.
Database Administrator / Software Engineer
Nelnet Business Solutions - FACTS-SIS
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.
Thanks.
SQL Backup Consultant Developer
Associate, Yohz Software
Beyond compression - SQL Backup goodies under the hood, updated for version 8
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.
SQL Backup Consultant Developer
Associate, Yohz Software
Beyond compression - SQL Backup goodies under the hood, updated for version 8
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.
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.
SQL Backup Consultant Developer
Associate, Yohz Software
Beyond compression - SQL Backup goodies under the hood, updated for version 8
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 )
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.
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
Senior Product Support Engineer
Redgate Software Ltd
Email: support@red-gate.com
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
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.
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.
SQL Backup Consultant Developer
Associate, Yohz Software
Beyond compression - SQL Backup goodies under the hood, updated for version 8
SQL Backup Consultant Developer
Associate, Yohz Software
Beyond compression - SQL Backup goodies under the hood, updated for version 8
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!
Thanks.
SQL Backup Consultant Developer
Associate, Yohz Software
Beyond compression - SQL Backup goodies under the hood, updated for version 8
Post subject: Slow Restore "Fixed Congrats" premature
Thanks.
SQL Backup Consultant Developer
Associate, Yohz Software
Beyond compression - SQL Backup goodies under the hood, updated for version 8
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
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.
SQL Backup Consultant Developer
Associate, Yohz Software
Beyond compression - SQL Backup goodies under the hood, updated for version 8
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.
Also, how large is your backup file? Would it be possible/feasible to send us a copy?
Thanks.
SQL Backup Consultant Developer
Associate, Yohz Software
Beyond compression - SQL Backup goodies under the hood, updated for version 8
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.
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.
Thanks.
SQL Backup Consultant Developer
Associate, Yohz Software
Beyond compression - SQL Backup goodies under the hood, updated for version 8