My backup times suddenly doubled

SQLJeff

I went from less than 4 hours to over 7.  the database grew roughly 200GB from 2.5TB to 2.7TB.  There haven't been any material changes and all-flash subsystem isn't having any issues that I am aware of.  Any thoughts on where to start? tried all 4 levels of compression.  the only change was adding CPUs to the VM and subsequent wizards suggested more threads.  Putting it back to same threads as before didn't help.  Post-backup copy and mirror also are dreadfully slow while a windows copy of SQB file takes an hour.

petey2

Could you please post the contents of the SQL Backup log file for a recent slow backup, and another for a backup that took 4 hours?  It may be helpful to compare the 2 logs to see where the delay is occuring.

The default folder where the logs are stored is C:\ProgramData\Red Gate\SQL Backup\Log\<instance name>.

Thank you.

SQLJeff

This one is slow, through put is half of the backup and naturally the duration is twice as long

SQL Backup log file 10.1.7.1571

-SQL "RESTORE DATABASE Medrisk

FROM DISK = '\\lucreserver\DBBackups\MedRisk\FULL_(local)_MedRisk_20201129_203006.sqb'

WITH 

MOVE 'Medrisk_Data' TO 'G:\SQLData\MedriskData.mdf',

MOVE 'MedRick_Data2' TO 'G:\SQLData\MedRisk_Data2.ndf',

MOVE 'MedRisk_Data3' TO 'H:\SQLData\MedRisk_Data3.ndf',

MOVE 'MedRisk_Data4' TO 'G:\SQLData\Medrisk_Data4.ndf', 

MOVE 'MedRisk_Data5' TO 'K:\SQLData\MedRisk_data5.ndf', 

MOVE 'MedRisk_Data6' TO 'J:\SQLData\MedRisk_data6.ndf', 

MOVE 'MedRisk_Data7' TO 'E:\SQLData\MedRisk_data7.ndf', 

MOVE 'Medrisk_log2' TO 'H:\SQLLogs\MedriskLog2.ldf',

MOVE 'Medrisk_Log' TO 'I:\SQLLogs\MedriskLog.ldf',

REPLACE, DISCONNECT_EXISTING,

Password = 'XXXXXXXXXX' "

-----------------------  PROCESSES COMPLETED SUCCESSFULLY   --------------------

11/30/2020 2:00:30 AM: Restoring Medrisk (database) from: 

11/30/2020 2:00:30 AM:   \\lucreserver\DBBackups\MedRisk\FULL_(local)_MedRisk_20201129_203006.sqb

11/30/2020 2:00:31 AM: ALTER DATABASE [Medrisk] SET ONLINE  RESTORE DATABASE [Medrisk]  FROM VIRTUAL_DEVICE = 'SQLBACKUP_DC6E795F-CED0-492D-A735-5A2AE9DDBF72', VIRTUAL_DEVICE = 'SQLBACKUP_DC6E795F-CED0-492D-A735-5A2AE9DDBF7201', VIRTUAL_DEVICE = 'SQLBACKUP_DC6E795F-CED0-492D-A735-5A2AE9DDBF7202', VIRTUAL_DEVICE = 'SQLBACKUP_DC6E795F-CED0-492D-A735-5A2AE9DDBF7203', VIRTUAL_DEVICE = 'SQLBACKUP_DC6E795F-CED0-492D-A735-5A2AE9DDBF7204', VIRTUAL_DEVICE = 'SQLBACKUP_DC6E795F-CED0-492D-A735-5A2AE9DDBF7205', VIRTUAL_DEVICE = 'SQLBACKUP_DC6E795F-CED0-492D-A735-5A2AE9DDBF7206', VIRTUAL_DEVICE = 'SQLBACKUP_DC6E795F-CED0-492D-A735-5A2AE9DDBF7207', VIRTUAL_DEVICE = 'SQLBACKUP_DC6E795F-CED0-492D-A735-5A2AE9DDBF7208', VIRTUAL_DEVICE = 'SQLBACKUP_DC6E795F-CED0-492D-A735-5A2AE9DDBF7209', VIRTUAL_DEVICE = 'SQLBACKUP_DC6E795F-CED0-492D-A735-5A2AE9DDBF7210', VIRTUAL_DEVICE = 'SQLBACKUP_DC6E795F-CED0-492D-A735-5A2AE9DDBF7211', VIRTUAL_DEVICE = 'SQLBACKUP_DC6E795F-CED0-492D-A735-5A2AE9DDBF7212', VIRTUAL_DEVICE = 'SQLBACKUP_DC6E795F-CED0-492D-A735-5A2AE9DDBF7213', VIRTUAL_DEVICE = 'SQLBACKUP_DC6E795F-CED0-492D-A735-5A2AE9DDBF7214', VIRTUAL_DEVICE = 'SQLBACKUP_DC6E795F-CED0-492D-A735-5A2AE9DDBF7215', VIRTUAL_DEVICE = 'SQLBACKUP_DC6E795F-CED0-492D-A735-5A2AE9DDBF7216', VIRTUAL_DEVICE = 'SQLBACKUP_DC6E795F-CED0-492D-A735-5A2AE9DDBF7217', VIRTUAL_DEVICE = 'SQLBACKUP_DC6E795F-CED0-492D-A735-5A2AE9DDBF7218', VIRTUAL_DEVICE = 'SQLBACKUP_DC6E795F-CED0-492D-A735-5A2AE9DDBF7219', VIRTUAL_DEVICE = 'SQLBACKUP_DC6E795F-CED0-492D-A735-5A2AE9DDBF7220', VIRTUAL_DEVICE = 'SQLBACKUP_DC6E795F-CED0-492D-A735-5A2AE9DDBF7221', VIRTUAL_DEVICE = 'SQLBACKUP_DC6E795F-CED0-492D-A735-5A2AE9DDBF7222', VIRTUAL_DEVICE = 'SQLBACKUP_DC6E795F-CED0-492D-A735-5A2AE9DDBF7223', VIRTUAL_DEVICE = 'SQLBACKUP_DC6E795F-CED0-492D-A735-5A2AE9DDBF7224', VIRTUAL_DEVICE = 'SQLBACKUP_DC6E795F-CED0-492D-A735-5A2AE9DDBF7225', VIRTUAL_DEVICE = 'SQLBACKUP_DC6E795F-CED0-492D-A735-5A2AE9DDBF7226', VIRTUAL_DEVICE = 'SQLBACKUP_DC6E795F-CED0-492D-A735-5A2AE9DDBF7227' WITH BUFFERCOUNT = 56, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576 , RECOVERY, MOVE 'Medrisk_Data' TO 'G:\SQLData\MedriskData.mdf', MOVE 'MedRick_Data2' TO 'G:\SQLData\MedRisk_Data2.ndf', MOVE 'MedRisk_Data3' TO 'H:\SQLData\MedRisk_Data3.ndf', MOVE 'MedRisk_Data4' TO 'G:\SQLData\Medrisk_Data4.ndf', MOVE 'MedRisk_Data5' TO 'K:\SQLData\MedRisk_data5.ndf', MOVE 'MedRisk_Data6' TO 'J:\SQLData\MedRisk_data6.ndf', MOVE 'MedRisk_Data7' TO 'E:\SQLData\MedRisk_data7.ndf', MOVE 'Medrisk_log2' TO 'H:\SQLLogs\MedriskLog2.ldf', MOVE 'Medrisk_Log' TO 'I:\SQLLogs\MedriskLog.ldf', REPLACE

11/30/2020 11:33:21 AM: Processed 62685688 pages for database 'Medrisk', file 'MedRisk_Data' on file 1.

11/30/2020 11:33:21 AM: Processed 63972240 pages for database 'Medrisk', file 'MedRick_Data2' on file 1.

11/30/2020 11:33:21 AM: Processed 63975912 pages for database 'Medrisk', file 'MedRisk_Data3' on file 1.

11/30/2020 11:33:21 AM: Processed 59766248 pages for database 'Medrisk', file 'MedRisk_Data4' on file 1.

11/30/2020 11:33:21 AM: Processed 3728704 pages for database 'Medrisk', file 'Medrisk_Data7' on file 1.

11/30/2020 11:33:21 AM: Processed 27218568 pages for database 'Medrisk', file 'MedRisk_Data5' on file 1.

11/30/2020 11:33:21 AM: Processed 76465424 pages for database 'Medrisk', file 'MedRisk_Data6' on file 1.

11/30/2020 11:33:21 AM: Processed 3854555 pages for database 'Medrisk', file 'MedRisk_Log' on file 1.

11/30/2020 11:33:21 AM: Processed 3769627 pages for database 'Medrisk', file 'MedRisk_Log2' on file 1.

11/30/2020 11:33:21 AM: RESTORE DATABASE successfully processed 365436965 pages in 32870.293 seconds (86.855 MB/sec).

11/30/2020 11:33:21 AM: SQL Backup process ended.

SQLJeff

One from May, this is a cross server restore

SQL Backup log file 10.1.0.1211

-SQL "RESTORE DATABASE Medrisk

FROM DISK = '\\lucreserver\DBBackups\MedRisk\FULL_(local)_MedRisk_20200430_204500.sqb'

WITH 

MOVE 'Medrisk_Data' TO 'G:\SQLData\MedriskData.mdf',

MOVE 'MedRick_Data2' TO 'G:\SQLData\MedRisk_Data2.ndf',

MOVE 'MedRisk_Data3' TO 'H:\SQLData\MedRisk_Data3.ndf',

MOVE 'MedRisk_Data4' TO 'G:\SQLData\Medrisk_Data4.ndf', 

MOVE 'MedRisk_Data5' TO 'H:\SQLData\MedRisk_data5.ndf', 

MOVE 'MedRisk_Data6' TO 'J:\SQLData\MedRisk_data6.ndf', 

MOVE 'Medrisk_log2' TO 'I:\SQLLogs\MedriskLog2.ldf',

MOVE 'Medrisk_Log' TO 'I:\SQLLogs\MedriskLog.ldf',

REPLACE, DISCONNECT_EXISTING,

Password = 'XXXXXXXXXX' "

-----------------------  PROCESSES COMPLETED SUCCESSFULLY   --------------------

5/1/2020 1:10:21 AM: Restoring Medrisk (database) from: 

5/1/2020 1:10:21 AM:   \\lucreserver\DBBackups\MedRisk\FULL_(local)_MedRisk_20200430_204500.sqb

5/1/2020 1:10:23 AM: ALTER DATABASE [Medrisk] SET ONLINE  RESTORE DATABASE [Medrisk]  FROM VIRTUAL_DEVICE = 'SQLBACKUP_E6E81AAD-F947-4BD1-AF2E-7A81E3C6EEE9', VIRTUAL_DEVICE = 'SQLBACKUP_E6E81AAD-F947-4BD1-AF2E-7A81E3C6EEE901', VIRTUAL_DEVICE = 'SQLBACKUP_E6E81AAD-F947-4BD1-AF2E-7A81E3C6EEE902', VIRTUAL_DEVICE = 'SQLBACKUP_E6E81AAD-F947-4BD1-AF2E-7A81E3C6EEE903', VIRTUAL_DEVICE = 'SQLBACKUP_E6E81AAD-F947-4BD1-AF2E-7A81E3C6EEE904', VIRTUAL_DEVICE = 'SQLBACKUP_E6E81AAD-F947-4BD1-AF2E-7A81E3C6EEE905', VIRTUAL_DEVICE = 'SQLBACKUP_E6E81AAD-F947-4BD1-AF2E-7A81E3C6EEE906', VIRTUAL_DEVICE = 'SQLBACKUP_E6E81AAD-F947-4BD1-AF2E-7A81E3C6EEE907', VIRTUAL_DEVICE = 'SQLBACKUP_E6E81AAD-F947-4BD1-AF2E-7A81E3C6EEE908', VIRTUAL_DEVICE = 'SQLBACKUP_E6E81AAD-F947-4BD1-AF2E-7A81E3C6EEE909', VIRTUAL_DEVICE = 'SQLBACKUP_E6E81AAD-F947-4BD1-AF2E-7A81E3C6EEE910', VIRTUAL_DEVICE = 'SQLBACKUP_E6E81AAD-F947-4BD1-AF2E-7A81E3C6EEE911', VIRTUAL_DEVICE = 'SQLBACKUP_E6E81AAD-F947-4BD1-AF2E-7A81E3C6EEE912', VIRTUAL_DEVICE = 'SQLBACKUP_E6E81AAD-F947-4BD1-AF2E-7A81E3C6EEE913' WITH BUFFERCOUNT = 28, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576 , RECOVERY, MOVE 'Medrisk_Data' TO 'G:\SQLData\MedriskData.mdf', MOVE 'MedRick_Data2' TO 'G:\SQLData\MedRisk_Data2.ndf', MOVE 'MedRisk_Data3' TO 'H:\SQLData\MedRisk_Data3.ndf', MOVE 'MedRisk_Data4' TO 'G:\SQLData\Medrisk_Data4.ndf', MOVE 'MedRisk_Data5' TO 'H:\SQLData\MedRisk_data5.ndf', MOVE 'MedRisk_Data6' TO 'J:\SQLData\MedRisk_data6.ndf', MOVE 'Medrisk_log2' TO 'I:\SQLLogs\MedriskLog2.ldf', MOVE 'Medrisk_Log' TO 'I:\SQLLogs\MedriskLog.ldf', REPLACE

5/1/2020 8:36:11 AM: Processed 61868896 pages for database 'Medrisk', file 'MedRisk_Data' on file 1.

5/1/2020 8:36:11 AM: Processed 63031848 pages for database 'Medrisk', file 'MedRick_Data2' on file 1.

5/1/2020 8:36:11 AM: Processed 62895840 pages for database 'Medrisk', file 'MedRisk_Data3' on file 1.

5/1/2020 8:36:11 AM: Processed 59179640 pages for database 'Medrisk', file 'MedRisk_Data4' on file 1.

5/1/2020 8:36:11 AM: Processed 9954776 pages for database 'Medrisk', file 'MedRisk_Data5' on file 1.

5/1/2020 8:36:11 AM: Processed 49364200 pages for database 'Medrisk', file 'MedRisk_Data6' on file 1.

5/1/2020 8:36:11 AM: Processed 85875 pages for database 'Medrisk', file 'MedRisk_Log' on file 1.

5/1/2020 8:36:11 AM: Processed 21314 pages for database 'Medrisk', file 'MedRisk_Log2' on file 1.

5/1/2020 8:36:11 AM: RESTORE DATABASE successfully processed 306402389 pages in 26729.346 seconds (89.555 MB/sec).

5/1/2020 8:36:11 AM: SQL Backup process ended.

petey2

Hi, thanks for sending the logs.

The May restore averaged 89.555 MB/sec, while the recent restore on November 30 averaged 86.855 MB/sec, which is fairly similar.  There is a slight discrepancy for the November restore, where SQL Server reports that the restore took 32870 seconds.  The restore started at 2 AM, and only completed at 11:33 AM, when it should have completed at 11:07 AM.  It's possible that the 24 extra minutes were due to SQL Server having to initialize the database files, if instant file initialization was not possible.

The throughput between backups and restores can be expected to be similar if you were backing up and restoring from the same servers using the same set of disks with the same connectivity.  If you copied a file of about 500 MB from the \\lucreserver\DBBackups\MedRisk\ share to the G:\SQLData\ folder on the server you are trying to restore to, what is the reported Windows transfer rate?

Thanks.