Under what conditions could restore of a huge database get delayed, in SQL server 2016, hosted on VM?

October 5, 2018 Andy DBA Stack Exchange 0

clip art of a double-quote character

Question

I have system where my database gets restored every night, and off late the restore is taking a lot longer from past few days.

Here is server config:

  • ES 2637 XEON @ 3.5 Ghz
  • Windows virtual server 2012 R2 hosted in a Hyper V environment
  • RAM: 128 GB
  • 8 CPUs
  • Ethernet: 500 Kps Throughput
  • Virtual Memory
    • Max Size:132,096 MB
    • Available: 39,395 MB
    • In Use: 92,701 MB

Version:

Microsoft SQL Server 2016 (SP2-CU1) (KB4135048) – 13.0.5149.0 (X64) May 19 2018 09:41:57 Copyright (c) Microsoft Corporation Enterprise Edition (64-bit) on Windows Server 2012 R2 Standard 6.3 (Build 9600: ) (Hypervisor)

  • Diff : RESTORE DATABASE successfully processed 3897077 pages in 825.165 seconds (36.896 MB/sec).
  • Full: RESTORE DATABASE successfully processed 51085865 pages in 3174.184 seconds (125.735 MB/sec).

Additional info:

  • Restores were completing in 3 hours; now, they are taking anywhere from 5 – 9 hours, about 2-3 times as long.
  • The size of the backup files hasn’t changed.
  • We are currently backing up to a single file.
  • To the best of my knowledge, there have been no changes to the system that would explain this.

Any ideas how to improve the restore speed ?

asked 2018-10-05 by datalearner

Answer

When I see someone complaining of backups “suddenly” changing, there are usually three things I look at first. In my experience, one of these three things is usually the cause.

1: Oops, there was a hardware change

Maybe a VM was v-motioned to a different host. Maybe there was a change in the storage configuration on the NAS/device that you’re backing up to. Maybe there was a network configuration change.

Pinpoint the date that backup performance changed, and work with your server/hardware team to figure out if anything changed here.

2: Change in DB size

This one is usually pretty easy to find. If you’re using database monitoring software of some sort, you should be able to go back and look at the historical data, and see that there was a significant change in the database size. (Full disclosure, I work for SentryOne, who makes database monitoring software.)

If you don’t have monitoring data, you can query msdb on the source server to look at the database backup size over time, and see if backup growth correlates to the time you noticed RESTORE scripts slowing down: 

SELECT database_name, backup_finish_date, backup_size
FROM msdb.dbo.backupset
WHERE [type] = 'd'
AND database_name = 'AdventureWorks2014' --Your database name here
ORDER BY backup_finish_date;

3: Change in transaction log number of VLFs

If it’s not the first two, it’s probably this one.
SQL Server breaks up the transaction log into “Virtual Log Files” — these are just logical buckets inside your .ldf file. On restore, SQL Server processes each of these VLFs in sequence, which means more VLFs can slow down your recovery. A high VLF count is bad.

Here’s how you can reproduce the problem using the AdventureWorks demo database. I restore the clean database, and test backup/restore. Then increase the VLF count and repeat the same backup/restore:

--
-- RESTORE AdventureWorks from a pristine copy from Github
--      https://github.com/Microsoft/sql-server-samples/releases/tag/adventureworks
-- 
USE master;
RESTORE DATABASE AdventureWorks2014
FROM DISK = 'C:\SQL\AdventureWorks2014.bak'
WITH MOVE 'AdventureWorks2014_Data' TO 'C:\SQL\AdventureWorks2014_Data.mdf'
    ,MOVE 'AdventureWorks2014_Log' TO 'C:\SQL\AdventureWorks2014_Log.ldf'
    ,REPLACE;
GO
--
-- Now do a backup & restore.
-- 
PRINT '----- BACKUP  1 -----';
BACKUP DATABASE AdventureWorks2014 TO DISK = 'C:\temp\ADVW2014.bak'     WITH INIT, COMPRESSION;
PRINT '----- RESTORE 1 -----';
RESTORE DATABASE AdventureWorks2014_RestoreTest FROM DISK = 'C:\temp\ADVW2014.bak'      WITH REPLACE, NORECOVERY
        , MOVE 'AdventureWorks2014_Data' TO 'C:\SQL\AdventureWorks2014_RestoreTest_Data.mdf' 
        , MOVE 'AdventureWorks2014_Log' TO 'C:\SQL\AdventureWorks2014_RestoreTest_Log.ldf' ;
GO
--
-- Lets really jack up the VLFs on this DB. Grow log file to 2GB in 1MB increments.
-- 
GO
USE AdventureWorks2014
DBCC SHRINKFILE (N'AdventureWorks2014_Log' , 1)
GO

DECLARE @i int = 51;
DECLARE @sql nvarchar(max);
WHILE @i <= 2000
BEGIN
    SET @sql = N'ALTER DATABASE [AdventureWorks2014] MODIFY FILE ( NAME = N''AdventureWorks2014_Log'', SIZE = ' + CONVERT(nchar(4),@i) + N'MB );';
    EXEC sp_executesql @sql;
    SET @i +=1;
END;
DBCC LOGINFO;
GO
--
-- Now do a backup &amp; restore.
-- 
PRINT '----- BACKUP  2 -----';
BACKUP DATABASE AdventureWorks2014 TO DISK = 'C:\temp\ADVW2014.bak'     WITH INIT, COMPRESSION;
PRINT '----- RESTORE 2 -----';
RESTORE DATABASE AdventureWorks2014_RestoreTest FROM DISK = 'C:\temp\ADVW2014.bak'      WITH REPLACE, NORECOVERY
        , MOVE 'AdventureWorks2014_Data' TO 'C:\SQL\AdventureWorks2014_RestoreTest_Data.mdf' 
        , MOVE 'AdventureWorks2014_Log' TO 'C:\SQL\AdventureWorks2014_RestoreTest_Log.ldf' ;
GO

The first backup/restore will generate output like this. Notice the speeds on backup (299.826 MB/sec) and restore (403.587 MB/sec):

----- BACKUP  1 -----
Processed 24328 pages for database 'AdventureWorks2014', file 'AdventureWorks2014_Data' on file 1.
Processed 4 pages for database 'AdventureWorks2014', file 'AdventureWorks2014_Log' on file 1.
BACKUP DATABASE successfully processed 24332 pages in 0.634 seconds (299.826 MB/sec).
----- RESTORE 1 -----
Processed 24328 pages for database 'AdventureWorks2014_RestoreTest', file 'AdventureWorks2014_Data' on file 1.
Processed 4 pages for database 'AdventureWorks2014_RestoreTest', file 'AdventureWorks2014_Log' on file 1.
RESTORE DATABASE successfully processed 24332 pages in 0.471 seconds (403.587 MB/sec).

The second backup/restore will generate output like this. Notice the speeds on backup (144.220 MB/sec) and restore (89.114 MB/sec):

----- BACKUP  2 -----
Processed 24328 pages for database 'AdventureWorks2014', file 'AdventureWorks2014_Data' on file 1.
Processed 3 pages for database 'AdventureWorks2014', file 'AdventureWorks2014_Log' on file 1.
BACKUP DATABASE successfully processed 24331 pages in 1.318 seconds (144.220 MB/sec).
----- RESTORE 2 -----
Processed 24328 pages for database 'AdventureWorks2014_RestoreTest', file 'AdventureWorks2014_Data' on file 1.
Processed 3 pages for database 'AdventureWorks2014_RestoreTest', file 'AdventureWorks2014_Log' on file 1.
RESTORE DATABASE successfully processed 24331 pages in 2.133 seconds (89.114 MB/sec).

To fix this, you essentially need to shrink & re-grow your log file in more appropriate chunks. You can see more information on this here, here, and here.

answered 2018-10-05 by Andy Mallon