May 5, 2011 at 9:19 am
I had a situation recently where restores of .trn files to a database in standby mode was taking between 8-12 hours per file.
I put a DBCC TRACEON(3004,3605,-1) to get extended information. Below is the trace information (I've removed lines that don't look too interesting indicated with "...") for a restore of a 5.5G .trn file.
I've marked the two areas in red where the bulk of the time is being spent...2 hours between log entries first and then 6 hours second. The time spent where it's actually restoring doesn't seem too bad for a 5.5G file...about 44 minutes including the zeroing.
I'm guessing that the 2 and 6 hours is related to the time being spent applying and writing to the .tuf file. In order to speed things up (otherwise the log shipping recipient would never catch up), I switched the database restore state to "No recovery mode". Once the backlog was processed I switched back to "Standby mode" and restore times once more seem reasonable.
Some additional info: this exact same database was also being log shipped to another physical server which did not suffer the same symptoms. The other server was virtually identical hardware except the disk for the databases were non-RAID...the slow server is RAID-5. I suspected file fragmentation and ran a defragger on the slow server which had no effect. System monitoring tools showed no particular stress on the slow machine...IO wasn't particularly intense and CPU usage was minimal. It was like SQL Server was just taking its sweet time. Unfortunately, I don't have trace logs for the exact same files to compare between the two servers during the slow performance. Once my server got caught up, I switched back to standby mode and restore times and trace logs are more or less identical on the two machines.
The trace:
2011-04-26 09:56:01.14 spid56 RestoreLog: Database QAI
...
2011-04-26 09:56:01.65 spid56 Restore: Undoing STANDBY for QAI
2011-04-26 11:58:10.48 spid56 SnipEndOfLog from LSN: (24837:114963:1)
2011-04-26 11:58:10.49 spid56 FixupLogTail() zeroing E:\SQLLOGS\log.ldf from 0xa67812600 to 0xa67814000.
2011-04-26 11:58:10.50 spid56 Zeroing E:\SQLLOGS\log.ldf from page 5454858 to 5455864 (0xa67814000 to 0xa67ff0000)
...
2011-04-26 12:06:11.80 spid56 Zeroing completed on E:\SQLLOGS\log.ldf
2011-04-26 12:06:18.20 spid56 Restore: Finished undoing STANDBY for QAI
2011-04-26 12:06:18.25 spid56 Restore: PreparingContainers
2011-04-26 12:06:18.26 spid56 Restore: Containers are ready
2011-04-26 12:06:18.27 spid56 Restore: Restoring backup set
2011-04-26 12:06:18.27 spid56 Restore: Transferring data to QAI
2011-04-26 12:06:18.27 spid56 Restore: Waiting for log zero on QAI
2011-04-26 12:06:18.28 spid56 Restore: LogZero complete
2011-04-26 12:35:25.55 spid56 FileHandleCache: 0 files opened. CacheSize: 10
2011-04-26 12:35:25.56 spid56 Restore: Data transfer complete on QAI
2011-04-26 12:35:25.57 spid56 Restore: Backup set restored
2011-04-26 12:35:25.58 spid56 Restore-Redo begins on database QAI
2011-04-26 12:41:32.41 spid56 Rollforward complete on database QAI
2011-04-26 12:41:32.45 spid56 Restore: Done with fixups
2011-04-26 12:41:32.48 spid56 Transitioning to STANDBY
2011-04-26 12:41:38.26 spid56 Starting up database 'QAI'.
2011-04-26 12:41:38.58 spid56 The database 'QAI' is marked RESTORING and is in a state that does not allow recovery to be run.
2011-04-26 12:42:33.79 spid56 Zeroing E:\SQLLOGS\log.ldf from page 6144833 to 6144893 (0xbb8682000 to 0xbb86fa000)
2011-04-26 12:42:33.80 spid56 Zeroing completed on E:\SQLLOGS\log.ldf
2011-04-26 19:06:20.74 spid56 Recovery is writing a checkpoint in database 'QAI' (46). This is an informational message only. No user action is required.
2011-04-26 19:12:57.97 spid56 Starting up database 'QAI'.
2011-04-26 19:13:13.09 spid56 Database is in STANDBY
Can anyone shed any light on what was going on? Thanks
May 5, 2011 at 9:36 am
Hi, how many VLF's in your transaction log?
from master db, run
DBCC LOGINFO (DBNAME)
May 5, 2011 at 9:46 am
Thanks for the response.
There are 147 VLFs. I checked at the time and 147 didn't seem like too many. It's the same number on both the fast and slow server which makes sense I think.
May 5, 2011 at 9:54 am
was there any additional information written to the log after the bit you posted? I.e. something about 'log was restored.... first LSN: xxxx last LSN' ?
If so, can you work out how many VLF's are being restored from the log backup: last LSN - first LSN?
May 5, 2011 at 10:42 am
2011-04-26 19:13:13.18 Backup Log was restored. Database: QAI, creation date(time): 2008/02/12(11:37:56), first LSN: 24837:114963:1, last LSN: 24922:13456:1, number of dump devices: 1, device information: (FILE=1, TYPE=DISK: {'E:\SQLBACKUPS\QAI_logshipping\QAI_20110415214601.trn'}). This is an informational message. No user action is required.
I think the calculation would be 24922-24837 = 85
May 6, 2011 at 1:34 am
6 hours does look like an extremely long time to create the undo file, even if the entire 5.5 GB contains uncommitted transactions. Can you compare the restore speed against the other server? You can check in msdb..restorehistory for the time the restore started, then look in the SQL Server log for the time the restore completed.
SQL BAK Explorer - read SQL Server backup file details without SQL Server.
Supports backup files created with SQL Server 2005 up to SQL Server 2017.
May 6, 2011 at 2:06 am
Ray Mond (5/6/2011)
6 hours does look like an extremely long time to create the undo file, even if the entire 5.5 GB contains uncommitted transactions.
I agree it does seem an extremely long time, but... my experience of restoring with standby has been similar, and I resorted to using standby only for the last log file of a bunch.
If the whole 5.5 GB contains uncommitted transactions, some of which were left over from the previous log file, then SQL Server has to re-apply the partial transactions from the previous undo file, then restore the log and apply the 5.5 GB of transactions, then roll back those same 5.5 GB worth of transactions and write them to a new undo file.
As we've seen from some other threads on this site, rolling back a large transaction takes an order of magnitude longer than making the changes in the first place.
May 6, 2011 at 8:07 am
I've got the contents of the restorehistory records for the .trn file listed below...I tried to format it but I couldn't get a nice display to work in using this HTML format. To summarize, everything looks exactly the same between the two servers but the slow server starts at 9:56 and finishes at 19:13, the fast server starts at 18:47 and finishes at 19:48. I joined the restorehistory up with the log file based on the start and end LSN...the way the file name is offset due to the timezone caused a bit of confusion.
From the fast server log file:
2011-04-16 19:48:11.68 Backup Log was restored. Database: QAI, creation date(time): 2008/02/12(11:37:56), first LSN: 24837:114963:1, last LSN: 24922:13456:1, number of dump devices: 1, device information: (FILE=1, TYPE=DISK: {'f:\logshipping\qai\QAI_20110415214601.trn'}). This is an informational message. No user action is required.
From msdb..restorehistory join backupset
Slow sever:
restore_history_id1909401
restore_date4/26/11 9:56
destination_database_nameQAI
backup_set_id1909780
restore_typeL
replace0
recovery0
restart0
stop_atNULL
device_count1
stop_at_mark_nameNULL
stop_beforeNULL
backup_set_id1909780
backup_set_uuid7ECD61F5-27AA-4378-A09E-6801CBC0E6E8
media_set_id1909778
first_family_number1
first_media_number1
last_family_number1
last_media_number1
catalog_family_number1
catalog_media_number1
position1
expiration_dateNULL
software_vendor_id4608
nameNULL
descriptionNULL
software_major_version9
software_minor_version0
software_build_version4035
time_zone-16
mtf_minor_version0
first_lsn24837000011496300000
last_lsn24922000001345600000
checkpoint_lsn24903000010213400000
database_backup_lsn19295000003680200000
database_creation_date37:56.0
backup_start_date46:01.0
backup_finish_date52:08.0
typeL
sort_order52
code_page0
compatibility_level90
database_version611
backup_size5653515776
database_nameQAI
server_nameHLDSQL01
machine_nameHLDSQL01
flags512
unicode_locale1033
unicode_compare_style196609
collation_nameSQL_Latin1_General_CP1_CI_AS
is_password_protected0
recovery_modelFULL
has_bulk_logged_data0
is_snapshot0
is_readonly0
is_single_user0
has_backup_checksums0
is_damaged0
begins_log_chain0
has_incomplete_metadata0
is_force_offline0
is_copy_only0
first_recovery_fork_guidB12C1E27-CFEF-4A71-98F8-94C8DACC6994
last_recovery_fork_guidB12C1E27-CFEF-4A71-98F8-94C8DACC6994
fork_point_lsnNULL
database_guidE10AB28E-3ADB-4055-AD59-F151742F8E76
family_guidB12C1E27-CFEF-4A71-98F8-94C8DACC6994
differential_base_lsnNULL
differential_base_guidNULL
Fast Server:
restore_history_id722936
restore_date4/16/11 18:47
destination_database_nameQAI
backup_set_id722917
restore_typeL
replace0
recovery0
restart0
stop_atNULL
device_count1
stop_at_mark_nameNULL
stop_beforeNULL
backup_set_id722917
backup_set_uuid7ECD61F5-27AA-4378-A09E-6801CBC0E6E8
media_set_id722917
first_family_number1
first_media_number1
last_family_number1
last_media_number1
catalog_family_number1
catalog_media_number1
position1
expiration_dateNULL
software_vendor_id4608
nameNULL
descriptionNULL
software_major_version9
software_minor_version0
software_build_version4035
time_zone-16
mtf_minor_version0
first_lsn24837000011496300000
last_lsn24922000001345600000
checkpoint_lsn24903000010213400000
database_backup_lsn19295000003680200000
database_creation_date37:56.0
backup_start_date46:01.0
backup_finish_date52:08.0
typeL
sort_order52
code_page0
compatibility_level90
database_version611
backup_size5653515776
database_nameQAI
server_nameHLDSQL01
machine_nameHLDSQL01
flags512
unicode_locale1033
unicode_compare_style196609
collation_nameSQL_Latin1_General_CP1_CI_AS
is_password_protected0
recovery_modelFULL
has_bulk_logged_data0
is_snapshot0
is_readonly0
is_single_user0
has_backup_checksums0
is_damaged0
begins_log_chain0
has_incomplete_metadata0
is_force_offline0
is_copy_only0
first_recovery_fork_guidB12C1E27-CFEF-4A71-98F8-94C8DACC6994
last_recovery_fork_guidB12C1E27-CFEF-4A71-98F8-94C8DACC6994
fork_point_lsnNULL
database_guidE10AB28E-3ADB-4055-AD59-F151742F8E76
family_guidB12C1E27-CFEF-4A71-98F8-94C8DACC6994
differential_base_lsnNULL
differential_base_guidNULL
May 6, 2011 at 8:24 am
That's certainly a big difference of 8 hours between the 2 servers to restore that transaction log. I know it's a long shot, but any chance the SQL Server process is running below normal priority?
SQL BAK Explorer - read SQL Server backup file details without SQL Server.
Supports backup files created with SQL Server 2005 up to SQL Server 2017.
May 6, 2011 at 9:48 am
It's running at normal priority...I did try setting it to high but it didn't make any difference.
May 9, 2011 at 4:09 am
Any chance it has something to do with the drive where the undo file is located, or perhaps you have some filter drivers that's intercepting the disk calls and performing some additional processing on the data/trx log/undo files e.g. the Hyperbac products?
SQL BAK Explorer - read SQL Server backup file details without SQL Server.
Supports backup files created with SQL Server 2005 up to SQL Server 2017.
November 17, 2015 at 11:01 am
Did anyone find any culprit to this?
We have similar situation on DR, one day log restore for all 40 DBs in STANDBY mode went up by about 15 times per backup file.
Nothing has changed on the box.
I checked on of the small DBs - has only 12 VLFs and no trans in some backups, takes "same exact" time as a restore of significantly larger tran logs.
It is a powerful DR box with ~1Tb of RAM allocated to SQL with nothing else running on the machine.
Any ideas?
- Anthony
-SQL 2K8 R2 10.50.4290.0 cluster, with 1Tb RAM, 64 cores.
November 17, 2015 at 11:14 am
No, we never did find a solution other than switching to "no recovery mode" and then back to standby once it was caught up or just backing up the source database and reestablishing the log shipping from scratch again. Fortunately, both disk and network speed have improved for us so much over the intervening years, starting again from scratch is pretty quick and easy now.
November 18, 2015 at 9:02 am
I had this issue in the past.
The culprit was a third party tool where log files that were not purged.
Redgate's SQL Backup didn't set a purge by default on the logs...so I had a server that had 100,000 log files.
Once I deleted the old log files and set the purge on the Server Options (SQL Backup Log Files section) in SQL Backup, the speed returned.
The servers I had involved the resources were very low and I couldn't figure out why it was taking so long.
Unsure if this is your issue, just throwing that out there.
November 18, 2015 at 9:27 am
Makes sense. I think the log shipping restore job inspects each file to see whether it has LSNs to be restored...scanning all those files would take a long time I imagine. That wasn't our issue though. Thanks.
Viewing 15 posts - 1 through 15 (of 15 total)
You must be logged in to reply to this topic. Login to reply