miércoles, 23 de abril de 2014

Troubleshoot: ora-600[kcrf_resilver_log_1] & ora-600[4193]

El sábado último recibí una llamada mientras manejaba, estacioné y atendí la llamada, se trataba de un buen amigo y cliente que tenía un problema con una de sus bases de datos. Ocurrió que como parte de un mantenimiento al servidor en el cual operaba, uno de los discos había presentado errores para ser reconocido. Eventualmente dieron con la causa del problema y lo resolvieron, el disco era nuevamente reconocido pero la base de datos no llegaba a abrir, les aparecía un error ORA-600 que no sabían cómo tratar y por tanto requerían de mi ayuda.

Ese día era uno particularmente recargado, estaba ayudando en los preparativos para celebrar el cumpleaños de mi pequeña Lucía, pero aparentemente no tomaría mucho tiempo atender esta urgencia, por lo que acordamos que haría unos minutos para al menos ver qué se podía hacer para resolver el problema. Mi amigo me proporcionó todos los datos necesarios para poder conectarme remotamente a su servidor, y pocos minutos después me encontraba revisando el archivo alert.log, encontrando lo siguiente:

Sat Apr 19 13:46:34 2014 
ALTER DATABASE OPEN
Beginning crash recovery of 1 threads
 parallel recovery started with 3 processes
Started redo scan
Errors in file d:\app\oracle\diag\rdbms\cts\cts\trace\cts_ora_3696.trc  (incident=85364):
ORA-00600: código de error interno, argumentos: [kcrf_resilver_log_1], [0x7FF62C56708], [2], [], [], [], [], [], [], [], [], []
Incident details in: d:\app\oracle\diag\rdbms\cts\cts\incident\incdir_85364\cts_ora_3696_i85364.trc
Aborting crash recovery due to error 600
Errors in file d:\app\oracle\diag\rdbms\cts\cts\trace\cts_ora_3696.trc:
ORA-00600: código de error interno, argumentos: [kcrf_resilver_log_1], [0x7FF62C56708], [2], [], [], [], [], [], [], [], [], []
Errors in file d:\app\oracle\diag\rdbms\cts\cts\trace\cts_ora_3696.trc:
ORA-00600: código de error interno, argumentos: [kcrf_resilver_log_1], [0x7FF62C56708], [2], [], [], [], [], [], [], [], [], []
ORA-600 signalled during: ALTER DATABASE OPEN...

Revisando en My Oracle Support (MOS) encontré el Note 1227666.1 ORA-00600 [kcrf_resilver_log_1] on restart after system crash, que señala como causa de este error: "There has been a lost write to the online redolog as a result of the crash. Instance recovery is not possible.", e indica que la solución es: "Restore the database and do point in time recovery to the most recent archivelog."

Son malas noticias, Oracle Support nos dice que hubo un error al grabar en los online redologs, no es posible hacer una recuperación automática de la instancia y en consecuencia hay que hacer un restore y luego un recover. Como quizás algunos ya sospechan, este problema no iba a ser tan fácil de resolver: esta base de datos no estaba en modo archive log, y no había backup físico al cual recurrir, las posibilidades de resolver el problema se redujeron drásticamente, pero el reto estaba dado y había que seguir intentando.

Como primer paso se realizó una copia física de todos los datafiles, online redologs y controlfiles, para posteriormente intentar hacer un recover:

SQL> recover database using backup controlfile until cancel;
ORA-00279: change 99446132 generated at 19/04/2014 10:00:45 needed for thread 1
ORA-00289: suggestion : D:\APP\ORACLE\FLASH_RECOVERY_AREA\CTS\ARCHIVELOG\2014_04_19\O1_MF_1_1157_%U_.ARC
ORA-00280: change 99446132 for thread 1 is in sequence #1157

Specify log: {=suggested | filename | AUTO | CANCEL}

Obviamente el archivelog sugerido no existía, pero para nuestra suerte la secuencia 1157 correspondía a un redolog que no tenia daño alguno:

SQL> select group#, sequence# from v$log;

    GROUP#  SEQUENCE# 
---------- ---------- 
         1       1156 
         2       1157 
         3       1155

Por lo que se procedió a alimentar ese online redolog al comando recover:

Specify log: {=suggested | filename | AUTO | CANCEL}
'D:\APP\ORACLE\ORADATA\CTS\REDO02.LOG'

Log applied.
Media recovery complete.

El mensaje "Media recovery complete" nos devolvió el alma al cuerpo, al parecer el problema estaba resuelto, pero faltaba el paso final, abrir la base de datos:

alter database open resetlogs;

Pero en lugar de que la base de datos fuese abierta normalmente, nos topamos con un nuevo ORA-600, tal como se ve en este extracto del alert.log:

Sat Apr 19 15:16:01 2014
alter database open resetlogs
RESETLOGS after complete recovery through change 99446132
Resetting resetlogs activation ID 4065219144 (0xf24e5248)
Sat Apr 19 15:16:03 2014
Setting recovery target incarnation to 3
Sat Apr 19 15:16:03 2014
Assigning activation ID 4085838382 (0xf388f22e)
Thread 1 opened at log sequence 1
  Current log# 1 seq# 1 mem# 0: D:\APP\ORACLE\ORADATA\CTS\REDO01.LOG
Successful open of redo thread 1
MTTR advisory is disabled because FAST_START_MTTR_TARGET is not set
Sat Apr 19 15:16:04 2014
SMON: enabling cache recovery
Successfully onlined Undo Tablespace 2.
Dictionary check beginning
Dictionary check complete
Verifying file header compatibility for 11g tablespace encryption..
Verifying 11g file header compatibility for tablespace encryption completed
SMON: enabling tx recovery
Database Characterset is WE8MSWIN1252
Errors in file d:\app\oracle\diag\rdbms\cts\cts\trace\cts_smon_4640.trc  (incident=87710):
ORA-00600: internal error code, arguments: [4193], [], [], [], [], [], [], [], [], [], [], []
Incident details in: d:\app\oracle\diag\rdbms\cts\cts\incident\incdir_87710\cts_smon_4640_i87710.trc
No Resource Manager plan active
Exception [type: ACCESS_VIOLATION, UNABLE_TO_READ] [ADDR:0x19698E97] [PC:0x9257D88, kgegpa()+38]
Dump file d:\app\oracle\diag\rdbms\cts\cts\trace\alert_cts.log

Luego de buscar en MOS, se encontró el Note 452662.1 Ora-600 [4193] When Opening Or Shutting Down A Database, que señala como causa: "..some kind of block corruption in either the redo or the undo block". El documento en cuestión analiza extensivamente los diversos escenarios posibles pero para este caso en particular solo se aplicó la solución para cuando la base de datos no logra ser abierta, y que consiste en desactivar la gestión automática del undo> y tratar de abrir la base de datos, si logra abrir entonces la corrupción no llegó a afectar al redo sino que se limitó a los segmentos de undo. Ese sería el escenario ideal, así que cruzamos los dedos y ejecutamos:

SQL> alter system set undo_management='MANUAL' scope=SPFILE sid='*';
System altered.

SQL> shutdown immediate
ORACLE instance shut down.

SQL> startup
ORACLE instance started.

Total System Global Area  167772160 bytes
Fixed Size                   787968 bytes
Variable Size              61864448 bytes
Database Buffers          104857600 bytes
Redo Buffers                 262144 bytes
Database mounted.
Database opened.

¡Fenomenal! Para nuestro alivio la base de datos abrió normalmente, lo cual fue comprobado con los mensajes en el archivo alert.log:

Sat Apr 19 15:28:08 2014
alter database open
Beginning crash recovery of 1 threads
 parallel recovery started with 3 processes
Started redo scan
Completed redo scan
 read 31 KB redo, 13 data blocks need recovery
Started redo application at
 Thread 1: logseq 1, block 3
Recovery of Online Redo Log: Thread 1 Group 1 Seq 1 Reading mem 0
  Mem# 0: D:\APP\ORACLE\ORADATA\CTS\REDO01.LOG
Completed redo application of 0.02MB
Completed crash recovery at
 Thread 1: logseq 1, block 66, scn 99466367
 13 data blocks read, 13 data blocks written, 31 redo k-bytes read
Sat Apr 19 15:28:09 2014
Thread 1 advanced to log sequence 2 (thread open)
Thread 1 opened at log sequence 2
  Current log# 2 seq# 2 mem# 0: D:\APP\ORACLE\ORADATA\CTS\REDO02.LOG
Successful open of redo thread 1
MTTR advisory is disabled because FAST_START_MTTR_TARGET is not set

La Nota indica también que ya que la base de datos logra abrir, se debe considerar que todas las transacciones han sido grabadas, y por tanto nos podemos deshacer del tablespace de undo que contiene los undo segments dañados y crear un nuevo tablespace que lo reemplace, por lo que continuamos con lo siguiente:

SQL> create undo tablespace UNDOTBS2 datafile
    'D:\APP\ORACLE\ORADATA\CTS\UNDOTBS02.DBF'
     size 100M reuse autoextend on;
Tablespace created.

SQL> alter system set undo_tablespace='UNDOTBS2' scope=SPFILE sid='*';
System altered.

SQL> alter system set undo_management='AUTO' scope=SPFILE sid='*';
System altered.

SQL> shutdown immediate
ORACLE instance shut down.

SQL> startup
ORACLE instance started.

Total System Global Area  167772160 bytes
Fixed Size                   787968 bytes
Variable Size              61864448 bytes
Database Buffers          104857600 bytes
Redo Buffers                 262144 bytes
Database mounted.
Database opened.

SQL> alter tablespace undotbs1 offline normal;
Tablespace altered.

SQL> drop tablespace UNDOTBS1 including contents and datafiles;
Tablespace dropped.

Concluidos estos últimos pasos, por fin pudimos dar el problema por resuelto, todos felices. Lo que parecía inicialmente un problema que tomaría unos pocos minutos en resolver terminó tomando casi una hora, pero fue una excelente oportunidad para aprender y sentir nuevamente la emoción y satisfacción de poder resolver problemas, que es la principal razón por la que me dedico a este negocio en primer lugar. Será hasta la próxima amigos!!!

Posts Relacionados:

¿Te pareció interesante este artículo?, ¿te quedaron algunas dudas?, ¿quieres sugerirme un tema a tratar?, pues déjame tus comentarios o envíame un email y para que NO te pierdas ningún Post, suscríbete por email ahora mismo!

4 comentarios, agrega el tuyo!

ibanez castrillon dijo...

Hola Enrique,
gracias por compartir los problemas y soluciones con nosotros. También pienso lo mismo en que la satisfacción de arreglar los problemas de este tipo y hace con que sigamos adelante.

J.Truch. dijo...

Buenas Enrique, acabo de leer el problema que te encontraste y como lo resolviste. Muchas gracias por los detalles ya que a veces me toca enfrentarme a casos similares y toda información es poca. Un saludo

Anónimo dijo...

Hola Enrique!!!
Gracias por compartir tu experiencia, disculpa que recién lo comente pero me interesó este caso, te hago algunas consultas (1) recuerdas si antes del problema la BD había bajado con normalidad, lo pregunto por que la primera nota habla de un crash (2) Entiendo que se malogró el undo segment y que no lo utilizaste pero sabemos que su contenido es necesario para asegurar la consistencia de la BD, entonces si se pudo levantar la BD es que no habían commit o rollback en proceso por el DBWR?, me comentas, gracias.
EduardoG.

Enrique Orbegozo dijo...

Hola "Anónimo", (1) hubo una caída de la base de datos, (2) sí, el segmento de UNDO ya no era necesario.
Saludos.