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

abril 23, 2014
No Comments

El sábado último recibí una llamada mientras manejaba, estacioné y la atendí. 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:

Copiar

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é la nota 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:

Copiar

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:

Copiar

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.

Copiar

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.

Copiar

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.

Copiar

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ó la nota 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:

Copiar

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:

Copiar

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:

Copiar

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!!!

¿Te pareció interesante este artículo?, ¿te quedaron algunas dudas?, ¿quieres sugerirme un tema a tratar?, pues déjame tus comentarios o ¡contáctame ahora mismo!