Oracle Database 11g: Termino inesperado da operação de Media Recovery com ORA-00600

Neste artigo, é narrado a investigação e a resolução de um problema ocorrido em um crítico database produtivo com versão 11.2.0.2 e um standby database configurado em "Real-time Apply" (sincronização em tempo real).

DATA             Dia  da Semana      Total    00h    01h    02h    03h
---------        -------------        ----    ---    ---    ---    ---
27-NOV-2014      Quinta-Feira         1207      0      5      0     12
28-NOV-2014      Sexta-Feira           728      1     84     21     97
29-NOV-2014      Sábado                668     90    372     99      1 
30-NOV-2014      Domingo                83      1      2      1      1      

OBS.: Foram omitidos os dados após as 03 horas, uma que esses dados são irrelevantes na discussão do problema.

De acordo com os dados de geração de archives, foram gerados no dia 29 de novembro de 2014 (29-NOV-2014, Sábado), 472 archives em aproximadamente 2 horas (01-02 e 02-03 = 01h até as 03h). A volumetria de geração de archives neste período (01h até as 03h) foi de 46GB, uma vez que cada redolog file possui o tamanho de 100MB (472 archives * 100MB = 46GB).

Analisando os logs do standby database, o processo MRP (Managed Recovery Process) aplicou com sucesso os archivelogs gerados até a sequência (log sequence) 147613, contudo ao submeter a aplicação do archivelog de sequência (log sequence) 147614, o processo é encerrado de forma inesperada retornando um erro interno (internalerror) ora-600.

Sat Nov 29 06:49:21 2014
Completed: ALTER DATABASE RECOVER MANAGED STANDBY DATABASE THROUGH ALL SWITCHOVER DISCONNECT USING CURRENT LOGFILE
Media Recovery Log  /u04/arch/ckpt/1_147614_751616314.dbf
Errors in file  /u00/app/oracle/diag/rdbms/ckptsby1/ckpt/trace/ckpt_pr00_21586.trc  (incident=582898):
ORA-00600:  internalerrorcode, arguments: [2619], [147614], [], [], [], [], [], [], [], [],  [], []
Incident details in:  /u00/app/oracle/diag/rdbms/ckptsby1/ckpt/incident/incdir_582898/ckpt_pr00_21586_i582898.trc

Primeiramente, vamos comparar qual a diferença numérica entre a quantidade de archivelogs gerados no primary database contra a quantidade de archivelogs aplicados no standby database.

Primary database

SQL> select  max(sequence#) from v$archived_log;

MAX(SEQUENCE#)
--------------
147729


Standby Database

SQL> select  max(sequence#) from v$archived_log where applied='YES';

MAX(SEQUENCE#)
--------------
147613

Ha um GAP de aplicação de 116 archives, onde o último archive gerado no primary database está na sequência (log sequence) 147729 e o último archive aplicado no standby database está na sequência (log sequence) 147613 (147729 - 147613 = 116). É importante ressaltar que não houve indisponibilidade do primary database, portanto o banco de dados está sofrendo transações, que consequentemente, ocorre geração de archivelogs.

Analisando os argumentos do erro interno ORA-600, é possível perceber que o segundo argumento "[147614]", refere-se a próxima sequência (log sequence) de archivelog a ser aplicado no standby database, já o primeiro argumento "[2619]" está relacionado com o local de armazenamento permanente dos archivelogs no standby database, o armazenamento permanente em questão é um disco, que eventualmente pode ou não, hospedar a área de FRA (Flash Recovery Area). 

Neste momento, temos um certeza, o problema está no archivelog de sequência (log sequence) 147614, onde há um corrupção deste arquivo, resta saber, se a corrupção foi ocasionada no momento da transferência do archivelog (Perda de dados no transporte do archive ou Problema físico no disco do standby database -  Nesta situação somente o archivelog do standby database está corrompido) ou se a corrupção foi ocasionada por problema físico no disco do primary database (Problema físico no disco do primary database - Nesta situação o archivelog está corrompido em ambos os database, primary database e standby database).
Seguindo nesta linha, iremos fazer comparações entre os archivelog de sequência (log sequence) 147614, que está no primary database e standby database, utilizando utilitários unix (diff e md5sum).

Verificação 1) Comparação de tamanho entre os arquivos.

oracle@oracle.1120.otn>ls  -ltr 1_147614_751616314.dbf_primary 1_147614_751616314.dbf_standby
-rw-r----- 1 oracle  oinstall 69396480 Sep 29 10:53 1_147614_751616314.dbf_standby
-rw-r----- 1 oracle  oinstall 69396480 Sep 29 10:56 1_147614_751616314.dbf_primary

Ambos os arquivos possuem o mesmo tamanho (69396480).

Verificação 2) Comparação hash entre os arquivos.

oracle@oracle.1120.otn>  md5sum 1_147614_751616314.dbf_primary 1_147614_751616314.dbf_standby
0e3011f7eb241fbfb55c435a9063837a1_147614_751616314.dbf_primary 
02c1f4e1ce28ea75ef539b37a5bedb2b1_147614_751616314.dbf_standby

Os submetidos a comparação hash, baseado no algoritmo MD5, é possível constatar que os arquivos estão diferentes, comparando os hash gerados, pelo utilitário md5sum.

Verificação 3) Comparação utilizando diff.

oracle@oracle.1120.otn>diff  1_147614_751616314.dbf_primary 1_147614_751616314.dbf_standby
Binary files  1_147614_751616314.dbf_primary and 1_147614_751616314.dbf_standby differ
oracle@oracle.1120.otn>  echo $?
2

Nesta última verificação, é feita a prova real, para comprovar a diferença entre os archivelogs.

Executando comparações físicas entre os archivelogs de sequência (log sequence) 147614 (1_147614_751616314.dbf_primary e 1_147614_751616314.dbf_standby), constatamos que existe diferenças entre eles, agora vamos aprofundar as investigações utilizando Log Miner.

Standby Database

SQL> EXECUTE  DBMS_LOGMNR.ADD_LOGFILE('/oracle/fra/archivelog/standby_database/1_147614_751616314.dbf_standby'  
,options => DBMS_LOGMNR.NEW);
   PL/SQL procedure  successfully completed.

SQL> EXECUTE  DBMS_LOGMNR.START_LOGMNR ();
 PL/SQL procedure  successfully completed.
 
SQL> SELECT rbasqn,  rbablk, rbabyte, operation, status, info FROM V$LOGMNR_CONTENTS;
   SELECT rbasqn, rbablk,  rbabyte, operation, status, info FROM V$LOGMNR_CONTENTS
   *
   ERROR at line 1:
   ORA-00600: internal error  code, arguments: [2619], [147614], [], [], [], [], [], [], [], [], [], []

Primary Database

SQL> EXECUTE  DBMS_LOGMNR.ADD_LOGFILE('/oracle/fra/archivelog/primary_database/1_147614_751616314.dbf_primary' 
 ,options => DBMS_LOGMNR.NEW);
PL/SQL procedure  successfully completed.

SQL> EXECUTE  DBMS_LOGMNR.START_LOGMNR ();
PL/SQL procedure  successfully completed.
 
SQL> SELECT rbasqn,  rbablk, rbabyte, operation, status, info FROM V$LOGMNR_CONTENTS;
    RBASQN      RBABLK    RBABYTE OPERATION   STATUS   INFO
----------   ---------  --------- ---------   -------  ----------------------
    147614        3262        368 COMMIT               0
    147614        3264        472 DELETE         2     Dictionary  Mismatch
    147614        3266        184 DELETE         2     Dictionary  Mismatch
    147614        3267        392 DELETE         2     Dictionary  Mismatch
    147614        3269        104 DELETE         2     Dictionary  Mismatch
    147614        3270        312 DELETE         2     Dictionary  Mismatch
    147614        3272         24 DELETE         2     Dictionary  Mismatch
    147614        3273        232 DELETE         2     Dictionary  Mismatch
    147614        3275         16 DELETE         2     Dictionary  Mismatch
    147614        3276        224 DELETE         2     Dictionary  Mismatch
    147614        3277        432 DELETE         2     Dictionary  Mismatch

Constatamos, após os teste de comparação física que os archivelog de sequência (log sequence) 147729 (1_147614_751616314.dbf_primary e 1_147614_751616314.dbf_standby) estão diferentes, ao passo que deveriam ser idênticos, utilizando o "Log Miner" foi possível concluir que o archivelog de sequência (log sequence) 147729, localizado no primary database, esta integro.Sendo assim, podemos fazer um recover no standby database de forma manual via sqlplus, utilizando o archivelog integro (1_147614_751616314.dbf_primary), localizado no primary database. Primeiramente faremos a transferências desde archivelog e posteriormente sua aplicação.

SQL> recover standby  database until cancel;

ORA-00279: change  2209191282893 generated at 09/29/2012
01:58:45 needed for thread  1
ORA-00289: suggestion  :/u04/arch/ckpt/1_147614_751616314.dbf
ORA-00280: change  2209191282893 for thread 1 is in sequence #147614
Specify log:  {=suggested | filename | AUTO | CANCEL}
/oracle/fra/archivelog/standby_database/1_147614_751616314.dbf

ORA-00279: change  2209191284000 generated at 09/29/2012 01:59:00 needed for thread 1
ORA-00289: suggestion :  /u04/arch/ckpt/1_147615_751616314.dbf
ORA-00280: change  2209191284000 for thread 1 is in sequence #147615
ORA-00278: log file  '/oracle/fra/archivelog/standby_database/1_147614_751616314.dbf' 
no longer  needed for this recovery
Specify log:  {=suggested | filename | AUTO | CANCEL}
CANCEL
 
Sat Nov 29 07:41:56 2014
ALTER DATABASE RECOVER  standby database until cancel
Media Recovery Start
startedlogmerger process
Sat Nov 29 07:41:56 2014
Managed Standby Recovery  not using Real Time Apply
Parallel Media Recovery  started with 32 slaves
ORA-279 signalled during:  ALTER DATABASE RECOVER  standby database  until cancel  ...
Sat Nov 29 07:42:56 2014
ALTER DATABASE RECOVER    LOGFILE  '/oracle/fra/archivelog/standby_database/1_147614_751616314.dbf'
Media Recovery Log  /oracle/fra/archivelog/standby_database/1_147614_751616314.dbf
ORA-279 signalled during:  ALTER DATABASE RECOVER    
LOGFILE  '/oracle/fra/archivelog/standby_database/1_147614_751616314.dbf'  ...

Após aplicar manualmente o archives 147614, o recover manual é interrompido voluntariamente (CANCEL), para que o processo background MRP, reinicie suas atividades, alteraremos o parâmetro DB_BROKER_START para valor TRUE, retomando assim, o funcionamento do Dataguard.

SQL> alter system set  dg_broker_start=true;
System altered.

Caso, não houver nenhum caso semelhante ao do archivelog 147614, então a tendência é que o standby database fique executando o processo de sincronização com o primary database, e permaneça assim até que seja necessário um Switchover ou ocorra algum incidente envolvendo o processo de sincronização.

Primary database

SQL> select  max(sequence#) from v$archived_log;

MAX(SEQUENCE#)
--------------
147849 

Standby Database

SQL> select  max(sequence#) from v$archived_log where applied='YES';

MAX(SEQUENCE#)
--------------
147848

Analisando o alert.log, é possível ver algumas mensagem de erro, que indica que o cabeçalho (Header) é o local corrompido do archivelog 147614.

Sat Nov 29 08:01:01 2014
archivelog header  validation failure for file /u04/arch/ckpt/1_147614_751616314.dbf
***
Corrupt block seq: 147614  blocknum=1.
Bad  header found during deleting archived log
Data in bad block - flag:1.  format:34. bno:1. seq:147614
beg:0 cks:47474
calculated check value:  47474
archivelog header  validation failure for file /u04/arch/ckpt/1_147614_751616314.dbf
Reread of seq=147614,  blocknum=1, file=/u04/arch/ckpt/1_147614_751616314.dbf, found same corrupt data
archivelog header  validation failure for file /u04/arch/ckpt/1_147614_751616314.dbf
Reread of seq=147614,  blocknum=1, file=/u04/arch/ckpt/1_147614_751616314.dbf, found same corrupt data
archivelog header  validation failure for file /u04/arch/ckpt/1_147614_751616314.dbf
Reread of seq=147614,  blocknum=1, file=/u04/arch/ckpt/1_147614_751616314.dbf, found same corrupt data
archivelog header  validation failure for file /u04/arch/ckpt/1_147614_751616314.dbf
Reread of seq=147614,  blocknum=1, file=/u04/arch/ckpt/1_147614_751616314.dbf, found same corrupt data
archivelog header  validation failure for file /u04/arch/ckpt/1_147614_751616314.dbf
Reread of seq=147614,  blocknum=1, file=/u04/arch/ckpt/1_147614_751616314.dbf, found same corrupt data
archivelog header  validation failure for file /u04/arch/ckpt/1_147614_751616314.dbf
***

Consultando no MOS (My Oracle Support), localizamos as notas 1138913.1 e 1422085.1, que descrevem as causas e a resolução de forma simplificada deste problema.

• ORA-600[2619] During Physical Standby Recovery (Doc ID 1138913.1)
• Downstream Capture Aborted with ORA-00600 [2619] and ORA-01280 (Doc ID 1422085.1)

Então .. temos a conclusão deste artigo. Esperamos que ele tenha sido útil para seguir com o  crescimento do seu conhecimento sobre as tecnologias Oracle.

Joel Perez é um DBA Especialista (Oracle ACE Director, OCM Cloud Admin. & OCM11g ). Com mais de 14 anos de experiência do mundo Oracle Technology, especializado em arquitetura e implementação de soluções como: Cloud, Alta disponibilidade, Disaster/Recovery, Upgrades, replicação e todos as áreas relacionadas com bancos de dados Oracle. Consultor internacional com deveres, conferências e atividades em mais de 50 países e inúmeros clientes em todo o mundo. Palestrante regular nos eventos Oracle em todo o mundo como: OTN LAD, OTN MENA, OTN APAC e muito mais. Joel sempre foi conhecido por ser pioneiro em tecnologia Oracle desde os primeiros dias de sua carreira sendo o primeiro latino-americano premiado como "OTN Expert" no ano de 2003 pela Oracle Corporation, um dos primeiros "ACE Oracle" no Oracle ACE Program no ano de 2004, um dos primeiros OCP Database Cloud Administrator em todo o mundo no ano de 2013 e como um das maiores realizações profissionais em sua carreira, recentemente ele foi homenageado como o primeiro "OCM Database Cloud Administrator" do mundo.

Basha Nassyam é um DBA. É um OCP 11g, com experiência em tecnologias como Oracle Data Guard, RMAN, RAC. Ele já fez mais de 90 configurações do Data Guard em diferentes plataformas, de não-RAC RAC e vice-versa. Ele fez migrações bem-sucedidas com "switchovers" e "failovers" a vários bancos de dados de produção crítica. Ele participa ativamente de fóruns Oracle utilizando o usuário "CKPT" e ganhou mais de 10.000 pontos (nível guru). Publica regularmente artigos em seu blog www.oracle-ckpt.com e é co-autor do livro "Guia de Administração do Oracle Data Guard 11gR2".

Carlos H. Y. Furushima é um especialista em banco de dados relacional, trabalhando como consultor de TI, atuando principalmente como o Oracle Database Administrator (DBA Oracle). Tem uma vasta experiência e conhecimento em “Performance, diagnosticand tuning", "High Availability", "Backup & Recovery" e "Exadata". Ele também está entusiasmado com sistema operacional Linux/Unix, onde contribui com o desenvolvimento do código do kernel Linux em parceria com a comunidade "GNU Linux", com criação e revisão de novas funcionalidades, melhorias e correções de bugs. Recentemente, Furushima divide seu tempo com consultoria especializada em banco de dados Oracle e estudos sobre "Oracle Internals", com o objetivo de descobrir e entender os benefícios do bancos de dados Oracle em plataforma Linux/Unix.

Este artigo foi revisto pela equipe de produtos Oracle e está em conformidade com as normas e práticas para o uso de produtos Oracle.