VDB recovery takes very long time
- Alexey Sosnovskih
When VDB gets to recovery phase, which is Step# 5 in the logs of VDB you may sometimes observe that the step takes very long time even though there is not much archived logs needed for recovery.
e.g. In the example below you can see that 3 archived logs were required for recovery
But the step took 1 hour 22 minutes to complete.
Also take a look at time which took to restore the archived logs, on average 20 sec each, so the IO was not a problem.
[2023-04-26 06:15:10.182] [INFO] Script executed in 1 hour 22 minutes 31 seconds
[2023-04-26 06:15:10.208] [INFO] =========== #5 Rman recover database completed. Execution output:
.....
.....
starting media recovery
channel ORA_DISK_1: starting archived log restore to default destination
channel ORA_DISK_1: restoring archived log
archived log thread=1 sequence=42040
channel ORA_DISK_1: reading from backup piece /main_pool/8060652855/DB/rg1qdf6k_1_1
channel ORA_DISK_2: starting archived log restore to default destination
channel ORA_DISK_2: restoring archived log
archived log thread=1 sequence=42041
channel ORA_DISK_2: reading from backup piece /main_pool/8060652855/DB/rh1qdf6k_1_1
channel ORA_DISK_3: starting archived log restore to default destination
channel ORA_DISK_3: restoring archived log
archived log thread=1 sequence=42042
channel ORA_DISK_3: reading from backup piece /main_pool/8060652855/DB/ri1qdf6k_1_1
channel ORA_DISK_3: piece handle=/main_pool/8060652855/DB/ri1qdf6k_1_1 tag=GI_INC_BACKUP
channel ORA_DISK_3: restored backup piece 1
channel ORA_DISK_3: restore complete, elapsed time: 00:00:16
channel ORA_DISK_2: piece handle=/main_pool/8060652855/DB/rh1qdf6k_1_1 tag=GI_INC_BACKUP
channel ORA_DISK_2: restored backup piece 1
channel ORA_DISK_2: restore complete, elapsed time: 00:00:27
channel ORA_DISK_1: piece handle=/main_pool/8060652855/DB/rg1qdf6k_1_1 tag=GI_INC_BACKUP
channel ORA_DISK_1: restored backup piece 1
channel ORA_DISK_1: restore complete, elapsed time: 00:00:37
archived log file name=/main_pool/8060652855/FRA/FAKKA/archivelog/2023_04_26/o1_mf_1_42040_l4l4fzrz_.arc thread=1 sequence=42040
channel default: deleting archived log(s)
archived log file name=/main_pool/8060652855/FRA/FAKKA/archivelog/2023_04_26/o1_mf_1_42040_l4l4fzrz_.arc RECID=3 STAMP=1135141099
archived log file name=/main_pool/8060652855/FRA/FAKKA/archivelog/2023_04_26/o1_mf_1_42041_l4l4g01o_.arc thread=1 sequence=42041
channel default: deleting archived log(s)
archived log file name=/main_pool/8060652855/FRA/FAKKA/archivelog/2023_04_26/o1_mf_1_42041_l4l4g01o_.arc RECID=2 STAMP=1135141094
archived log file name=/main_pool/8060652855/FRA/FAKKA/archivelog/2023_04_26/o1_mf_1_42042_l4l4g0gm_.arc thread=1 sequence=42042
channel default: deleting archived log(s)
archived log file name=/main_pool/8060652855/FRA/FAKKA/archivelog/2023_04_26/o1_mf_1_42042_l4l4g0gm_.arc RECID=1 STAMP=1135141081
unable to find archived log
If you run query on V$SESSION while VDB is recovering you may see the major wait event “recovery read”,
SID|SERIAL| SQLEXEC|SQL_ID |EVENT |USERN |OSUSER |FGRDPID |BGRDPID |MACHINE |COMMAND |LOGTIME | SECS| block
------|------|---------|-------------|----------------------|------------|----------|--------|--------|--------------------|--------|---------------|-----|------
481| 1574| | |parallel recovery chan|SYS |oracle |19303 |19303 |p-odaqadb01 |alter da|20230502 09:12:| 2129|
505| 51609| | |recovery read |SYS |oracle |19809 |19809 |p-odaqadb01 |alter da|20230502 09:12:| 2127|
1| 6289| | |recovery read |SYS |oracle |19815 |19815 |p-odaqadb01 |alter da|20230502 09:12:| 2127|
489| 36904| | |recovery read |SYS |oracle |19789 |19789 |p-odaqadb01 |alter da|20230502 09:12:| 2127|
497| 46846| | |recovery read |SYS |oracle |19793 |19793 |p-odaqadb01 |alter da|20230502 09:12:| 2127|
449| 4354| 16777216|3j508yd77gq49|class slave wait |SYS |oracle |94313 |94373 |p-odaqadb01 |alter da|20230502 09:09:| 726|
329| 9554| 16777216|d53229v8xq0kp|SQL*Net message to cli|SYS |oracle |17790 |17796 |p-odaqadb01 |select |20230502 09:47:| 0|
If you see this wait event for recovery sessions you need to turn off db_lost_write_protect
The wait 'Recovery Read' is on I/O and we can't tune this from the Database side other than set db_lost_write_protect=NONE
Ref doc# Data Guard Apply Lag on Top wait event "Recovery Read" for 12.1.0.2 and Earlier Workaround (Doc ID 2910785.1)