In the middle of last month an oracle Data Guard standby database of our production system there had shown the very weird message in its ALERT log file.
......
Mon Mar 15 10:01:16 2021
Media Recovery Waiting for thread 1 sequence 2768 (in transit)
Recovery of Online Redo Log: Thread 1 Group 4 Seq 2768 Reading mem 0
Mem# 0: /u01/oradata/DGstandby/standbyredo01.log
Mon Mar 15 11:01:06 2021
RFS[4]: Selected log 5 for thread 1 sequence 2769 dbid 298590189 branch 1059239666
Mon Mar 15 11:01:09 2021
Archived Log entry 58618 added for thread 1 sequence 2768 ID 0x1ab474d5 dest 1:
Mon Mar 15 11:21:04 2021
Errors in file /u01/app/oracle/diag/rdbms/DGstandby/DGstandby/trace/DGstandby_pr1e_28452.trc (incident=494753):
ORA-00600: internal error code, arguments: [3020], [3], [1820], [12584732], [], [], [], [], [], [], [], []
ORA-10567: Redo is inconsistent with data block (file# 3, block# 1820, file offset is 14909440 bytes)
ORA-10564: tablespace UNDOTBS1
ORA-01110: data file 3: '/u01/oradata/DGstandby/undotbs01.dbf'
ORA-10560: block type 'KTU UNDO BLOCK'
Incident details in: /u01/app/oracle/diag/rdbms/DGstandby/DGstandby/incident/incdir_494753/DGstandby_pr1e_28452_i494753.trc
Mon Mar 15 11:21:13 2021
Dumping diagnostic data in directory=[cdmp_20210315112113], requested by (instance=1, osid=28452 (PR1E)), summary=[incident=494753].
Mon Mar 15 11:21:19 2021
Use ADRCI or Support Workbench to package the incident.
See Note 411.1 at My Oracle Support for error and packaging details.
Slave exiting with ORA-600 exception
Errors in file /u01/app/oracle/diag/rdbms/DGstandby/DGstandby/trace/DGstandby_pr1e_28452.trc:
ORA-00600: internal error code, arguments: [3020], [3], [1820], [12584732], [], [], [], [], [], [], [], []
ORA-10567: Redo is inconsistent with data block (file# 3, block# 1820, file offset is 14909440 bytes)
ORA-10564: tablespace UNDOTBS1
ORA-01110: data file 3: '/u01/oradata/DGstandby/undotbs01.dbf'
ORA-10560: block type 'KTU UNDO BLOCK'
Mon Mar 15 11:21:20 2021
Errors in file /u01/app/oracle/diag/rdbms/DGstandby/DGstandby/trace/DGstandby_mrp0_28299.trc (incident=494313):
ORA-00600: internal error code, arguments: [3020], [3], [1820], [12584732], [], [], [], [], [], [], [], []
ORA-10567: Redo is inconsistent with data block (file# 3, block# 1820, file offset is 14909440 bytes)
ORA-10564: tablespace UNDOTBS1
ORA-01110: data file 3: '/u01/oradata/DGstandby/undotbs01.dbf'
ORA-10560: block type 'KTU UNDO BLOCK'
Incident details in: /u01/app/oracle/diag/rdbms/DGstandby/DGstandby/incident/incdir_494313/DGstandby_mrp0_28299_i494313.trc
Mon Mar 15 11:21:21 2021
Sweep [inc][494753]: completed
Sweep [inc][494313]: completed
Sweep [inc2][494753]: completed
Use ADRCI or Support Workbench to package the incident.
See Note 411.1 at My Oracle Support for error and packaging details.
Recovery Slave PR1E previously exited with exception 600
Mon Mar 15 11:21:22 2021
MRP0: Background Media Recovery terminated with error 448
Errors in file /u01/app/oracle/diag/rdbms/DGstandby/DGstandby/trace/DGstandby_pr00_28328.trc:
ORA-00448: normal completion of background process
Managed Standby Recovery not using Real Time Apply
Dumping diagnostic data in directory=[cdmp_20210315112122], requested by (instance=1, osid=28299 (MRP0)), summary=[incident=494313].
Recovery interrupted!
Recovered data files to a consistent state at change 22382148475
MRP0: Background Media Recovery process shutdown (DGstandby)
Mon Mar 15 11:22:21 2021
Sweep [inc2][494313]: completed
......
As you can see from the prior partial alert log contents some critical messages with the highlighting green color. Yes, you have found that the ORA-00600 error with four arguments [3020], [3], [1820], [12584732] ……, and beneath the 1 – 4 lines you’ll notice the message is obviously clear: UNDO data block with datafile 3 (UNDO tablespace) is inconsistent with REDO.
Next you continue to observe the underneath hightlighting lines, MRP0 process shutdown by oracle itself, hence Managed Standby Recovery not using Real Time Apply for my oracle Data Guard standby database.
Oh, my God!
Immediately I use the command DBV to check whether UNDO datafile 3 has several corrupt logical data blocks.
[oracle@DGstandby ~]$ dbv file =/u01/oradata/DGstandby/undotbs01.dbf blocksize=8192
DBVERIFY: Release 11.2.0.4.0 - Production on Tue Mar 16 12:16:03 2021
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
DBVERIFY - Verification starting : FILE = /u01/oradata/DGstandby/undotbs01.dbf
DBVERIFY - Verification complete
Total Pages Examined : 3308160
Total Pages Processed (Data) : 0
Total Pages Failing (Data) : 0
Total Pages Processed (Index): 0
Total Pages Failing (Index): 0
Total Pages Processed (Other): 3308159
Total Pages Processed (Seg) : 15869
Total Pages Failing (Seg) : 0
Total Pages Empty : 1
Total Pages Marked Corrupt : 0
Total Pages Influx : 0
Total Pages Encrypted : 0
Highest block SCN : 907311993 (5.907311993)
Fortunately the UNDO datafile has none corrupt logic data blocks. Next I searched “ORA-00600:[3020] ORA-10567” on Google by coincidence the ranking 3rd blog post is the same as my case.
Now I start to do the begin backup of UNDO tablespace on primay database and next scp undotbs01.dbf to standby database as well as do the end backup of UNDO tablespace.
SYS@DGprimary> alter tablespace UNDOTBS1 begin backup;
Tablespace altered.
[oracle@DGprimary DGprimary]$ scp undotbs01.dbf oracle@xx.xxx.x.xx:/u01/oradata/DGstandby/
oracle@xx.xxx.x.xx's password:
undotbs01.dbf 100% 25GB 57.3MB/s 07:31
SYS@DGprimary> alter tablespace UNDOTBS1 end backup;
Tablespace altered.
In the mean time creating standby controlfile and next scp to the standby database from primary database.
SYS@DGprimary> alter database create standby controlfile as '/u01/oradata/DGprimary/standby.ctl';
Database altered.
[oracle@DGprimary DGprimary]$ ls -lrht standby.ctl
-rw-r----- 1 oracle oinstall 20M Mar 17 09:30 standby.ctl
[oracle@DGprimary DGprimary]$
[oracle@DGprimary DGprimary]$ scp standby.ctl oracle@xx.xxx.x.xx:/u01/oradata/DGstandby/
oracle@xx.xxx.x.xx's password:
standby.ctl 100% 20MB 19.9MB/s 00:00
At this very moment I go to restart my Data Guard standby database.
SYS@DGstandby> shutdown immediate;
Database closed.
Database dismounted.
ORACLE instance shut down.
SYS@DGstandby> startup
!!!WARNING!!!
This database may be accessed only by authorized users for Legitimate
business purposes. Unauthorized use of this database is strictly
prohibited and may be subject to criminal prosecution. By continuing
to use this database you indicate your consent to these conditions of
use. LOG OFF IMMEDIATELY if you do not agree to the conditions stated
in this warning.
ORACLE instance started.
Total System Global Area 1.6034E+11 bytes
Fixed Size 2261848 bytes
Variable Size 2.6844E+10 bytes
Database Buffers 1.3314E+11 bytes
Redo Buffers 352444416 bytes
Database mounted.
!!!WARNING!!!
This database may be accessed only by authorized users for Legitimate
business purposes. Unauthorized use of this database is strictly
prohibited and may be subject to criminal prosecution. By continuing
to use this database you indicate your consent to these conditions of
use. LOG OFF IMMEDIATELY if you do not agree to the conditions stated
in this warning.
SYS@DGstandby>
Next I have seen receiving archived logs from primary database on the standby database’s ALERT log file.
......
Wed Mar 17 09:35:19 2021
Media Recovery Log /u01/oradata/arch/1_2769_1059239666.dbf
Wed Mar 17 09:35:21 2021
Primary database is in MAXIMUM PERFORMANCE mode
RFS[1]: Assigned to RFS process 2026
RFS[1]: Selected log 4 for thread 1 sequence 2826 dbid 298590189 branch 1059239666
Wed Mar 17 09:35:22 2021
RFS[2]: Assigned to RFS process 2036
RFS[2]: Selected log 5 for thread 1 sequence 2825 dbid 298590189 branch 1059239666
Wed Mar 17 09:35:40 2021
Archived Log entry 58675 added for thread 1 sequence 2825 ID 0x1ab474d5 dest 1:
Wed Mar 17 09:36:42 2021
Media Recovery Log /u01/oradata/arch/1_2770_1059239666.dbf
Wed Mar 17 09:37:40 2021
Media Recovery Log /u01/oradata/arch/1_2771_1059239666.dbf
Wed Mar 17 09:38:51 2021
Media Recovery Log /u01/oradata/arch/1_2772_1059239666.dbf
......
Wed Mar 17 10:14:38 2021
Media Recovery Log /u01/oradata/arch/1_2819_1059239666.dbf
Media Recovery Log /u01/oradata/arch/1_2820_1059239666.dbf
Wed Mar 17 10:14:52 2021
Media Recovery Log /u01/oradata/arch/1_2821_1059239666.dbf
Wed Mar 17 10:15:08 2021
Media Recovery Log /u01/oradata/arch/1_2822_1059239666.dbf
Media Recovery Log /u01/oradata/arch/1_2823_1059239666.dbf
Wed Mar 17 10:15:48 2021
Media Recovery Log /u01/oradata/arch/1_2824_1059239666.dbf
Wed Mar 17 10:16:37 2021
Media Recovery Log /u01/oradata/arch/1_2825_1059239666.dbf
Wed Mar 17 10:17:03 2021
Incomplete Recovery applied until change 22391814304 time 03/17/2021 09:35:21
Completed Standby Crash Recovery.
Wed Mar 17 10:17:04 2021
SMON: enabling cache recovery
Dictionary check beginning
Dictionary check complete
Database Characterset is AL32UTF8
No Resource Manager plan active
replication_dependency_tracking turned off (no async multimaster replication found)
Physical standby database opened for read only access.
Completed: ALTER DATABASE OPEN
As you can see from my previous alert log file standby database has been open. Now I am going to do the operation with Managed Standby Recovery starting Real Time Apply.
SYS@DGprimary> select open_mode from v$database;
OPEN_MODE
----------------------------------------
READ ONLY
SYS@DGprimary> ALTER DATABASE RECOVER MANAGED STANDBY DATABASE USING CURRENT LOGFILE DISCONNECT FROM SESSION;
Database altered.
SYS@DGprimary> select open_mode from v$database;
OPEN_MODE
----------------------------------------
READ ONLY WITH APPLY
Nice!!! Finally I checked the view v$managed_standby and v$dataguard_stats, MRP0 has been working so far.
SYS@DGprimary> SELECT process,pid,status,sequence#,block#,blocks,delay_mins FROM v$managed_standby;
PROCESS PID STATUS SEQUENCE# BLOCK# BLOCKS DELAY_MINS
------------------ ---------- ------------------------ ---------- ---------- ---------- ----------
ARCH 1902 CLOSING 2825 661504 773 0
ARCH 1904 CLOSING 2826 987136 2041 0
ARCH 1907 CONNECTED 0 0 0 0
ARCH 1909 CONNECTED 0 0 0 0
RFS 2014 IDLE 0 0 0 0
RFS 2026 IDLE 2827 78062 49 0
RFS 2036 IDLE 0 0 0 0
MRP0 14310 APPLYING_LOG 2827 78110 2097152 0
8 rows selected.
SYS@DGprimary> COL name FOR a22
SYS@DGprimary> COL value FOR a12
SYS@DGprimary> COL unit FOR a28
SYS@DGprimary> COL time_computed FOR a19
SYS@DGprimary> COL datum_time FOR a19
SYS@DGprimary>
SYS@DGprimary> SELECT * FROM v$dataguard_stats;
NAME VALUE UNIT TIME_COMPUTED DATUM_TIME
---------------------- ------------ ---------------------------- ------------------- -------------------
transport lag +00 00:00:00 day(2) to second(0) interval 03/17/2021 10:23:47 03/17/2021 10:23:45
apply lag +00 00:00:00 day(2) to second(0) interval 03/17/2021 10:23:47 03/17/2021 10:23:45
apply finish time day(2) to second(3) interval 03/17/2021 10:23:47
estimated startup time 25 second 03/17/2021 10:23:47
Welcome to give a feedback or comment as always, hope this note help you as well.
Update Apr 03, 2021
I have forgotten to mention that manually trying to start MRP firstly in my mind but after half an hour which has been terminated by oracle. In other words at that moment oracle is not able to allow starting redo log real time apply on Data Guard primary database in case of showing ORA-00600 [3020].
Focusing and Concentrating Oracle Recipes, Tips and Techniques 