Skip to main content
Delphix

Increasing the Performance of Recovery Log Scan During ASE LOAD DATABASE, LOAD TRANSACTION and MOUNT (KBA1790)

  1. Last updated
  2. Save as PDF
 

 

KBA

KBA#1790

Applicable Delphix Versions

Click here to view the versions of the Delphix engine to which this article applies
Major Release All Sub Releases
6.0 6.0.0.0, 6.0.1.0, 6.0.1.1, 6.0.2.0, 6.0.2.1, 6.0.3.0, 6.0.3.1, 6.0.4.0, 6.0.4.1, 6.0.4.2, 6.0.5.0, 6.0.6.0, 6.0.6.1, 6.0.7.0, 6.0.8.0, 6.0.8.1, 6.0.9.0, 6.0.10.0, 6.0.10.1, 6.0.11.0

5.3

 5.3.0.0, 5.3.0.1, 5.3.0.2, 5.3.0.3, 5.3.1.0, 5.3.1.1, 5.3.1.2, 5.3.2.0, 5.3.3.0, 5.3.3.1, 5.3.4.0, 5.3.5.0, 5.3.6.0, 5.3.7.0, 5.3.7.1, 5.3.8.0, 5.3.8.1, 5.3.9.0

5.2

5.2.2.0, 5.2.2.1, 5.2.3.0, 5.2.4.0, 5.2.5.0, 5.2.5.1, 5.2.6.0, 5.2.6.1

5.1

5.1.0.0, 5.1.1.0, 5.1.2.0, 5.1.3.0, 5.1.4.0, 5.1.5.0, 5.1.5.1, 5.1.6.0, 5.1.7.0, 5.1.8.0, 5.1.8.1, 5.1.9.0, 5.1.10.0

5.0

5.0.1.0, 5.0.1.1, 5.0.2.0, 5.0.2.1, 5.0.2.2, 5.0.2.3, 5.0.3.0, 5.0.3.1, 5.0.4.0, 5.0.4.1, 5.0.5.0, 5.0.5.1, 5.0.5.2, 5.0.5.3, 5.0.5.4

Issue

ASE goes through several phases (ANALYSIS, REDO and UNDO) after a database dump or transaction log is loaded. The same phases take place when Delphix mounts a database using the ASE "MOUNT DATABASE" command. There are some ASE configuration parameters that can improve performance during these phases.

Some customers have seen periods where during the REDO phase, ASE just seems to stop progressing. In this example, we see it progress through the ANALYSIS phase and starts working through the REDO phase:

[2018-09-30 18:03:32,529][INFO][ase.dbc.ASEJDBCAccessorImpl#messageHandler:1139][Worker-ASEValidatedSyncWorker.6][] ASE message 12562 : Started estimating recovery log boundaries for database 'dx8nf5f1eAs4uz36733Hu_acme'.
[2018-09-30 18:03:32,529][INFO][ase.dbc.ASEJDBCAccessorImpl#messageHandler:1139][Worker-ASEValidatedSyncWorker.6][] ASE message 12563 : Completed estimating recovery log boundaries for database 'dx8nf5f1eAs4uz36733Hu_acme'.
[2018-09-30 18:03:32,529][INFO][ase.dbc.ASEJDBCAccessorImpl#messageHandler:1139][Worker-ASEValidatedSyncWorker.6][] ASE message 12564 : Started ANALYSIS pass for database 'dx8nf5f1eAs4uz36733Hu_acme'.
[2018-09-30 18:03:32,529][INFO][ase.dbc.ASEJDBCAccessorImpl#messageHandler:1139][Worker-ASEValidatedSyncWorker.6][] ASE message 12565 : Completed ANALYSIS pass for database 'dx8nf5f1eAs4uz36733Hu_acme'.
[2018-09-30 18:03:32,529][INFO][ase.dbc.ASEJDBCAccessorImpl#messageHandler:1139][Worker-ASEValidatedSyncWorker.6][] ASE message 12566 : Started full REDO pass for database 'dx8nf5f1eAs4uz36733Hu_acme'. The total number of log records to process is 55254425.
[2018-09-30 18:03:32,529][INFO][ase.dbc.ASEJDBCAccessorImpl#messageHandler:1139][Worker-ASEValidatedSyncWorker.6][] ASE message 3476 : Redo pass for database 'dx8nf5f1eAs4uz36733Hu_acme': 2762721 records done (4%); 52491704 records left.[2018-09-30 18:03:32,530][INFO][ase.dbc.ASEJDBCAccessorImpl#messageHandler:1139][Worker-ASEValidatedSyncWorker.6][] ASE message 3476 : Redo pass for database 'dx8nf5f1eAs4uz36733Hu_acme': 5525442 records done (9%); 49728983 records left.
...etc...
[2018-09-30 18:03:32,531][INFO][ase.dbc.ASEJDBCAccessorImpl#messageHandler:1139][Worker-ASEValidatedSyncWorker.6][] ASE message 3476 : Redo pass for database 'dx8nf5f1eAs4uz36733Hu_acme': 24864489 records done (44%); 30389936 records left.

It got all the way up to 44% but then just stops logging for almost 12 hours and 12 minutes. Here it picks up again:

[2018-10-01 06:15:29,177][INFO][ase.dbc.ASEJDBCAccessorImpl#messageHandler:1139][Worker-ASEValidatedSyncWorker.6][] ASE message 3476 : Redo pass for database 'dx8nf5f1eAs4uz36733Hu_acme': 27627210 records done (49%); 27627215 records left.
...etc...
[2018-10-01 06:15:29,178][INFO][ase.dbc.ASEJDBCAccessorImpl#messageHandler:1139][Worker-ASEValidatedSyncWorker.6][] ASE message 3476 : Redo pass for database 'dx8nf5f1eAs4uz36733Hu_acme': 55254420 records done (99%); 5 records left.
...etc...
[2018-10-01 06:15:29,180][DEBUG][ase.dbc.ASEJDBCAccessorImpl#executeWithProgress:1061][Worker-ASEValidatedSyncWorker.6][] 9 405801 1: Backup Server: 4.58.1.1: Database dx8nf5f1eAs4uz36733Hu_acme: 10115642 kilobytes LOADED.

In this particular case, repeatedly running the "DBCC SHOWRECOVERY" command showed it was slowly progressing but doing very little I/O.

Troubleshooting

Monitor the Delphix debug logs:

  • Grepping for "ASE message 3476" can give you a sense of how quickly it is progressing through the REDO phase.
  • Grepping for "ASE message 3477" can give you a sense of how quickly it is progressing through the UNDO phase.

Using the "DBCC SHOWRECOVERY" command provides much more detailed information on how much recovery is necessary, how long each phase took and how much I/O was necessary:

DBCC TRACEON(3604)
go
DBCC SHOWRECOVERY [(dbid | dbname)]
go

Resolution

There are two ASE configuration parameters that may help:

  1. In ASE 15.7 SP60 and higher, there is a configuration parameter named "enable large pool for load". ASE automatically tunes the caches for recovery on reboot, but does not do this for  load database and load transaction recovery, since it could impact other databases on a production server. Delphix recommends that the staging ASE instance be separate from the ASE production instance and ASE instances hosting VDBs so enabling this parameter should have a beneficial impact on performance.
  2. Specify the "relaxed" strategy for replacing the cache in the default data cache:
sp_cacheconfig ‘default data cache’, relaxed
go

Since the mount/unmount process invalidates the pages anyway, the page chain is really just unneeded overhead on the staging server.

Additional Information

 

Privacy Policy Terms of Use Legal About
© 2024 Delphix Corp