History | Log In     View a printable version of the current page.  
Issue Details (XML | Word | Printable)

Key: QA-63
Type: Oracle - Internals Oracle - Internals
Status: Closed Closed
Resolution: Answered
Priority: Major Major
Assignee: ubTools Support
Reporter: ubTools Support
Votes: 0
Watchers: 0
Operations

If you were logged in you would be able to see more operations.
Questions & Answers

ORA-600 [3020] on the standby after adding a datafile on primary

Created: 16/Feb/18 10:31 AM   Updated: 16/Feb/18 12:47 PM
Fix Version/s: None

Product Version: 11.2.0.4
Operating System: Linux
Host Name: .
Database Name: .


 Description  « Hide
Problem:

The customer has added a datafile on the primary database. After the datafile was created on the standby database, ORA-600 [3020] was encountered while applying an archivelog to this datafile on standby.

ORA-600 [3020]:

This is called a 'STUCK RECOVERY'.

  There is an inconsistency between the information stored in the redo 
  and the information stored in a database block being recovered.

Ref: Doc ID 30866.1



 All   Comments   Change History      Sort Order: Ascending order - Click to sort in descending order
ubTools Support - 16/Feb/18 10:36 AM - edited
PROBLEM OCCURRENCE:

Adding datafile on the Primary:

Tue Feb 13 07:44:52 2018
ALTER TABLESPACE MENKUL2018_DATA
  ADD DATAFILE '/orassd/orcl/datafile/menkul2018_data02.dbf'
  SIZE 5G
  AUTOEXTEND ON
  NEXT 100M
  MAXSIZE UNLIMITED
Completed: ALTER TABLESPACE MENKUL2018_DATA
  ADD DATAFILE '/orassd/orcl/datafile/menkul2018_data02.dbf'
  SIZE 5G
  AUTOEXTEND ON
  NEXT 100M
  MAXSIZE UNLIMITED
Tue Feb 13 07:45:38 2018

Applying Archivelogs on the Standby:

Tue Feb 13 07:46:55 2018
ALTER DATABASE RECOVER AUTOMATIC STANDBY DATABASE UNTIL CHANGE 69358633799
Media Recovery Start
 started logmerger process
Tue Feb 13 07:46:55 2018
Managed Standby Recovery not using Real Time Apply
Parallel Media Recovery started with 24 slaves
Media Recovery Log /u01/ORCL/archive/52b86b9a_1_91417_922239972.arc
Tue Feb 13 07:47:07 2018
Successfully added datafile 232 to media recovery
Datafile #232: '/u01/oracle/app/oradata/ORCL/datafile/ORCL_STBY/datafile/o1_mf_menkul20_f84vg0lt_.dbf'
Incomplete Recovery applied until change 69358633799 time 02/13/2018 07:45:38
Tue Feb 13 07:47:08 2018
Media Recovery Complete (ORCL)
Completed: ALTER DATABASE RECOVER AUTOMATIC STANDBY DATABASE UNTIL CHANGE 69358633799

.....

Tue Feb 13 08:26:55 2018
ALTER DATABASE RECOVER AUTOMATIC STANDBY DATABASE UNTIL CHANGE 69358697423
Media Recovery Start
 started logmerger process
Tue Feb 13 08:26:55 2018
Managed Standby Recovery not using Real Time Apply
Parallel Media Recovery started with 24 slaves
Media Recovery Log /u01/ORCL/archive/52b86b9a_1_91425_922239972.arc
Tue Feb 13 08:26:57 2018
Errors in file /u01/oracle/app/diag/rdbms/orcl_stby/ORCL/trace/ORCL_pr0i_21945.trc  (incident=131897):
ORA-00600: internal error code, arguments: [3020], [232], [3], [973078531], [], [], [], [], [], [], [], []
ORA-10567: Redo is inconsistent with data block (file# 232, block# 3, file offset is 24576 bytes)
ORA-10564: tablespace MENKUL2018_DATA
ORA-01110: data file 232: '/u01/oracle/app/oradata/ORCL/datafile/ORCL_STBY/datafile/o1_mf_menkul20_f84vg0lt_.dbf'
ORA-10560: block type '0'
Incident details in: /u01/oracle/app/diag/rdbms/orcl_stby/ORCL/incident/incdir_131897/ORCL_pr0i_21945_i131897.trc
Tue Feb 13 08:26:59 2018

ubTools Support - 16/Feb/18 11:06 AM - edited
ANALYSIS of the RESULT:
Ref: ORCL_pr0i_21945.trc

Data:

REDO Dump:

KCOX_FUTURE: CHANGE IN FUTURE OF BLOCK

*** 2018-02-13 08:26:56.826
RECOVERY STUCK AT BLOCK 3 OF FILE 232
Redo record scn: 0x0010.2619b07d
CHANGE #1 TYP:0 CLS:12 AFN:232 DBA:0x3a000003 OBJ:4294967295
 SCN:0x0010.2618c0fb SEQ:2 OP:22.5 ENC:0 RBL:0

Buffer read during recovery:
.....

The stuck recovery happened at file#232 block#3 with KCOX_FUTURE: CHANGE IN FUTURE OF BLOCK information.

Block Dump:

buffer tsn: 141 rdba: 0x3a000003 (232/3)
scn: 0x0000.00000000 seq: 0x01 flg: 0x05 tail: 0x00000001
frmt: 0x02 chkval: 0x9d03 type: 0x00=unknown
on-disk scn: 0x0.0

SCN is 0, type is unknown. flg is 0x05:

Where flg: 0x05 contains flag 0x1 (unused,unformatted block).

Ref: Oracle Doc ID 17896895.8

Comment:

The change vector was expecting SCN:0x0010.2618c0fb on the block. But, the SCN on the block was 0x0000.00000000.

Oracle was trying to apply archivelog to an unformatted block. REDO in archivelog is beyond block in datafile. This inconsistency causes stuck recovery.


ubTools Support - 16/Feb/18 12:12 PM - edited
ANALYSIS of the ROOT CAUSE:

Data:

The datafile has been created at sequence#91417 and the problem happened at sequence#91425 at file#232 block#3.

REDO Dump Commands:

SQL> ALTER SYSTEM dump  logfile '/u01/ORCL/archive/52b86b9a_1_91417_922239972.arc' dba min 232 3 dba max 232 3;

System altered.

SQL> ALTER SYSTEM dump  logfile '/u01/ORCL/archive/52b86b9a_1_91418_922239972.arc' dba min 232 3 dba max 232 3;

System altered.

SQL> ALTER SYSTEM dump  logfile '/u01/ORCL/archive/52b86b9a_1_91419_922239972.arc' dba min 232 3 dba max 232 3;

System altered.

SQL> ALTER SYSTEM dump  logfile '/u01/ORCL/archive/52b86b9a_1_91420_922239972.arc' dba min 232 3 dba max 232 3;

System altered.

SQL> ALTER SYSTEM dump  logfile '/u01/ORCL/archive/52b86b9a_1_91421_922239972.arc' dba min 232 3 dba max 232 3;

System altered.

SQL> ALTER SYSTEM dump  logfile '/u01/ORCL/archive/52b86b9a_1_91422_922239972.arc' dba min 232 3 dba max 232 3;

System altered.

SQL>  ALTER SYSTEM dump  logfile '/u01/ORCL/archive/52b86b9a_1_91423_922239972.arc' dba min 232 3 dba max 232 3;

System altered.

SQL> ALTER SYSTEM dump  logfile '/u01/ORCL/archive/52b86b9a_1_91424_922239972.arc' dba min 232 3 dba max 232 3;

System altered.

SQL>  ALTER SYSTEM dump  logfile '/u01/ORCL/archive/52b86b9a_1_91425_922239972.arc' dba min 232 3 dba max 232 3;

System altered.

SQL> 

REDO Dumps:

DUMP OF REDO FROM FILE '/u01/ORCL/archive/52b86b9a_1_91417_922239972.arc'
.....
REDO RECORD - Thread:1 RBA: 0x016519.00000765.01e8 LEN: 0x0058 VLD: 0x01
SCN: 0x0010.2618c0fb SUBSCN:  1 02/13/2018 07:44:59
(LWN RBA: 0x016519.00000763.0010 LEN: 0004 NST: 0002 SCN: 0x0010.2618c0f9)
CHANGE #1 TYP:1 CLS:12 AFN:232 DBA:0x3a000003 OBJ:4294967295 SCN:0x0010.2618c0fb SEQ:1 OP:22.4 ENC:0 RBL:0
ktfbbfo - File BitMap Block Format:
BitMap Control:
RelFno: 232, BeginBlock: 128, Flag: 0, First: 0, Free: 63488

REDO RECORD - Thread:1 RBA: 0x016519.00000763.0010 LEN: 0x0244 VLD: 0x05
SCN: 0x0010.2618c0fb SUBSCN:  1 02/13/2018 07:44:59
CHANGE #1 TYP:0 CLS:69 AFN:3 DBA:0x00c018c0 OBJ:4294967295 SCN:0x0010.2618c0ee SEQ:1 OP:5.4 ENC:0 RBL:0
ktucm redo: slt: 0x0007 sqn: 0x000060e7 srt: 0 sta: 9 flg: 0x2 ktucf redo: uba: 0x3000319f.07d5.06 ext: 2 spc: 7334 fbi: 0
CHANGE #2 MEDIA RECOVERY MARKER SCN:0x0000.00000000 SEQ:0 OP:17.30 ENC:0
Add datafiles to tablespace #141
file #232  relative file #232. '/orassd/orcl/datafile/menkul2018_data02.dbf'
flags(reuse): 0x0
Checkpointed at scn:  0x0010.2618c0f0 02/13/2018 07:44:56
.....
DUMP OF REDO FROM FILE '/u01/ORCL/archive/52b86b9a_1_91425_922239972.arc'
.....
REDO RECORD - Thread:1 RBA: 0x016521.0001a022.0034 LEN: 0x0040 VLD: 0x01
SCN: 0x0010.2619b07d SUBSCN: 14 02/13/2018 08:23:51
(LWN RBA: 0x016521.00019dca.0010 LEN: 1012 NST: 0002 SCN: 0x0010.2619b069)
CHANGE #1 TYP:0 CLS:12 AFN:232 DBA:0x3a000003 OBJ:4294967295 SCN:0x0010.2618c0fb SEQ:2 OP:22.5 ENC:0 RBL:0
ktfbbredo - File BitMap Block Redo:
Use Bits:

Comment:

The datafile has been created at sequence#91417 by REDO OP code 17.30, which means:

the OP:17.30 redo which adds the <file#> datafile

Ref: Oracle Doc ID 27229389.8

There are some other OP codes 22.4 and 5.4 before adding the datafile.

Change Vector for OP Code 22:4:

It tries to change absolute file#232 (AFN:232 DBA:0x3a000003). This is the problem that Oracle tries to apply a change vector to a file which was not created yet.

Change Vector for OP Code 5:4:

It tries to change absolute file#3 (AFN:3 DBA:0x00c018c0). This is a different file. So, it's out of the scope.


ubTools Support - 16/Feb/18 12:26 PM - edited
SOLUTION:

Problem:

Oracle tries to apply archivelog to a file which was not created on standby yet.

Fix:

This is Oracle bug 27229389.

Workaround:

Copy datafile from primary to standby that doesn't require corrupted archivelogs.