viernes, 11 de julio de 2014

De cómo un clon nos puede ayudar con un patch (updated to 12c)

Cada vez que vamos a aplicar un patch o un patch set update (PSU), el procedimiento tradicional implica detener todos los procesos que se estén ejecutando en el Oracle home directory involucrado, lo cual obliga a que dejemos de prestar servicio para iniciar el patching, proceso que si bien es relativamente fácil y sencillo, está sujeto a eventuales fallas que, de ocurrir, pueden llevar a una situación de crisis en la cual el DBA debe identificar el problema y tratar de resolverlo, u optar por dar marcha atrás. En este artículo que he publicado en Oracle Technology Network les explico cómo hacerlo. ¡Que disfruten la lectura!


Siga leyendo >>

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

viernes, 27 de junio de 2014

¿Archive log perdido? No reconstruya su Standby (al estilo 12c)

Se ha escrito hasta la saciedad (incluso yo) sobre cómo re-sincronizar una base de datos Standby en aquellos casos en los cuales la sincronización se suspendió y al tratar de reiniciarla nos topamos con que al menos un archivelog requerido ya no está disponible. En este artículo que he publicado en Toad World les explico lo simple que resulta resolver este problema cuando están usando Oracle Server 12c. ¡Que disfruten la lectura!

Siga leyendo >>

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

miércoles, 11 de junio de 2014

Troubleshoot: perdiendo el control

Me encontraba sumergido en un proyecto de diseño e implementación de un Oracle RAC 11gR2, en las instalaciones de uno de mis clientes regulares, cuando fui interrumpido por el jefe del proyecto. Me empezó a comentar sobre sobre un problema de desempeño que venían experimentando con la base de datos principal, que aún se encontraba en Oracle RAC 10gR2, y que como parte del proyecto sería actualizada a 11gR2. Habían ya identificado que el evento principal era buffer busy waits y me pidieron darle una mirada para ver que se podía hacer para resolverlo. La tarea parecía simple, era solo cuestión de identificar el objeto problemático, pero como ya es habitual se trataba solo de la punta del iceberg. ¿Quieres saber qué paso?, pues acompáñenme en esta interesante historia, sacada de la vida real.

First round
Según lo indicaban los reportes de AWR el escenario inicial era el siguiente:

Top 5 Timed Events                                         Avg %Total
~~~~~~~~~~~~~~~~~~                                        wait   Call
Event                                 Waits    Time (s)   (ms)   Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
buffer busy waits                   116,522     113,002    970   43.1 Concurrenc
log file switch completion           61,227      59,589    973   22.7 Configurat
log file sync                        26,675      18,098    678    6.9     Commit
db file sequential read           2,167,894      17,680      8    6.7   User I/O
enq: CF - contention                 28,209      13,492    478    5.1      Other

. . .

Segments by Buffer Busy Waits
           Tablespace                      Subobject  Obj.          Busy    % of
Owner         Name    Object Name            Name     Type         Waits Capture
---------- ---------- -------------------- ---------- ----- ------------ -------
SYSTEM     TBS_OTROS  DB_AUDIT_LOGON                  TABLE       98,134   85.30
USU_MONI   TOOLS      TEST_MONITOR_DB                 TABLE        7,843    6.82
USU_SIC    TBS_OTROS  REGSERVPROVSIC                  TABLE        4,048    3.52
USU_ACP    TBS_OTROS  USUARIO_DB                      TABLE        3,149    2.74
USU_SIC    TBS_OTROS  REGSERVSIC                      TABLE          863     .75

A todas luces el segmento problemático era la tabla db_audit_logon. Ocurría que al momento de establecerse una conexión con la base de datos se ingresaba una fila en dicha tabla, pero parte de la lógica incluía una búsqueda de filas dentro de la misma tabla, búsqueda que se hacía por un criterio para el cual no existía índice alguno. Esto hacía que se realizara un full table scan sobre dicha tabla, la cual iba demorando más y más con el tiempo, por el normal crecimiento en el número de filas, al punto que se había tornado insoportable para el usuario final.

Como medida inmediata recomendé la creación de un nuevo índice, que luego de implementado permitió eliminar el problema, o al menos eso pensaba yo, ya que retomé las tareas propias del proyecto principal en el que estaba envuelto al momento de recibir esta consulta.

Myth buster
Aconteció que luego de resuelto el evento buffer busy waits, el equipo de DBAs empezó a atacar los siguientes eventos en la lista: log file switch completion y log file sync. Como dio la casualidad de que estaban trasladando los disk groups a un nuevo storage server, y alentados por la recomendación expresa del proveedor del mismo, optaron por trasladar los online redo logs a un disk group exclusivo para ellos, sobre discos SSD. Como resultado inmediato el evento log file sync desapareció y el evento log file switch completion disminuyó a la tercera parte.

Con tan buenos resultados obtenidos, o así creían, me consultaron si no era una excelente idea incluir en mi diseño del nuevo Oracle RAC 11gR2 un disk group exclusivo para los online redo logs y desde luego con discos SSD. Vi sus rostros de alegría transformarse en rostros de asombro cuando les respondí negativamente: los discos SSD no son eficientes para grabación, por el contrario: tienden a volverse cada vez más lentos cuando son sujetos a una alta tasa de grabación, que es como justamente se comportan los online redo logs. El que observaran una mejora en los tiempos no tenía relación con los discos SSD, tenía relación con el hecho de que ahora los online redo logs residían en discos exclusivos, con capacidad de consumir todo el I/O disponible, y ya no como antes, cuando lo compartían con otros 4TB de datos sujetos a lectura y escritura intensivas. En otras palabras: podrían lograr el mismo efecto, e incluso uno mejor, si hubiesen empleado discos tradicionales, lo cual de paso tiene la ventaja adicional de representar un desembolso menor, ya que son muchos más baratos que su contraparte SSD.

La fe mueve... ¿eventos de espera?
A pesar de la explicación dada, y ya que habían tenido mejoras moviendo los online redo logs a discos SSD, continuaron con el siguiente paso en sus planes: mover también el controlfile, con la esperanza de deshacerse del evento enq: CF - contention. Lamentablemente para ellos el efecto fue prácticamente nulo, así que optaron por abrir un Service Request con Oracle Support. El primer error fue abrirlo en español, las idas y venidas con las traducciones hicieron que el avance fuera muy lento, y como es usual en el soporte de primer nivel, finalmente lo primero que les solicitaron fue que actualizaran la versión de Oracle Server, ya que evidentemente 10gR2 ya no cuenta con soporte premiere actualmente. El Ingeniero a cargo del caso no pensaban escalar el pedido de atención mientras no lo hicieran, así que a mi cliente no le quedó más alternativa que solicitarme que nuevamente dejara en pausa el proyecto inicial y me encargara de este problema con carácter de urgente y prioritario, ya que la operatividad estaba seriamente comprometida, y así las cosas acepté el reto.

Second round
Tomemos en cuenta que el nuevo escenario era el siguiente:

Top 5 Timed Events                                         Avg %Total
~~~~~~~~~~~~~~~~~~                                        wait   Call
Event                                 Waits    Time (s)   (ms)   Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
CPU time                                         61,576          42.5
enq: CF - contention                 45,676      19,029    417   13.1 Other
log file switch completion           17,882      17,077    955   11.8 Configurat
control file sequential read     18,658,312      16,081      1   11.1 System I/O
db file sequential read           5,490,434       9,251      2    6.4 User I/O

Este evento de espera era nuevo para mí, y lo disponible en My Oracle Support no apuntaba a solución alguna, por lo que empecé por abrir un nuevo Service Request, pero esta vez en inglés, y dejando en claro por anticipado que la situación era extremadamente crítica y que no había tiempo para upgrades. Esta vez lo primero que pidieron fue verificar con el equipo de storage para comprobar que no hubiese un problema a esos niveles, considerando que la base de datos había sido movida a un nuevo storage array. Desde luego por allí no iba el problema, ya que incluso se estaban usando discos SSD, así que pasaron a lo siguiente: revisar que no se generaran demasiados log switches. Cuando les mostramos que solo ocurrían entre 2 a 6 por hora, también fue descartado, y apuntaron a otra posible causa: encontraron unos mensajes de error en el alert.log y sospecharon de un problema con la conectividad con el servidor que opera con physical standby, y pidieron investigarlo con el equipo de redes.

Fri Jun 8 06:00:37 2014
Errors in file /u01/admin/db/bdump/db_lns1_2195896.trc:
ORA-03135: connection lost contact
Fri Jun 8 06:00:37 2014
LGWR: I/O error 3135 archiving log 321 to 'dbcntg'
Fri Jun 8 06:03:56 2014
ARC1: Attempting destination LOG_ARCHIVE_DEST_2 network reconnect (3113)
ARC1: Destination LOG_ARCHIVE_DEST_2 network reconnect abandoned
PING[ARC1]: Error 3113 when pinging standby eppscntg.
Fri Jun 8 06:40:30 2014
Errors in file /u01/admin/db/bdump/db_arc1_745792.trc:
ORA-16146: standby destination control file enqueue unavailable
Fri Jun 8 06:40:30 2014
Master background archival failure: 16146

Se les explicó que todos los días a las 6am se suspendía el servicio de la base de datos en standby para aplicar los archived redo logs acumulados durante el día, por lo cual la base de datos primaria perdía la conexión, y no era por tanto un problema de conectividad. Nuevamente a esperar.

Gotcha!
Ya llevábamos algunos días con el problema sin resolver, y empezaban a correr rumores de que los usuarios se disponían a tomar por asalto el centro de cómputo (), cuando Oracle Support nos indica que leamos el Note 753893.1 Degraded performance on standby due to waits on controlfile enqueue (no se molesten en buscarlo, es un documento interno, no disponible para el público en general). En este documento se señala que ante una gran cantidad de archived redo logs registrados en el controlfile, puede presentarse el evento enq: CF – Contention, y que la idea era no tener más de mil registros en uso. Con esta nueva información hicimos la investigación del caso:

SQL> SELECT type, records_total, records_used 
       FROM v$controlfile_record_section 
      WHERE type='ARCHIVED LOG';

TYPE                         RECORDS_TOTAL RECORDS_USED
---------------------------- ------------- ------------
ARCHIVED LOG                        116912        84612

¡Bingo! Casi 85 mil archived redo logs registrados. ¿Cómo llegaron allí teniendo en cuenta que el parámetro control_file_record_keep_time tenía el valor 1 (1 día)? Buena pregunta, confieso que no tengo la respuesta, no era el objetivo en ese momento investigarlo, los usuarios estaban al borde del colapso, así que simplemente nos enfocamos en implementar la solución:

SQL> exec dbms_backup_restore.resetcfilesection(11);

RMAN> catalog start with '+FRA/db/archivelog';

SQL> SELECT type, records_total, records_used 
       FROM v$controlfile_record_section 
      WHERE type='ARCHIVED LOG';

TYPE                         RECORDS_TOTAL RECORDS_USED
---------------------------- ------------- ------------
ARCHIVED LOG                        116912          336

El efecto fue inmediato: los eventos desaparecieron por completo, tanto los relacionados con el controlfile como los relacionados con los online redo logs, y la situación volvió a la normalidad.

Top 5 Timed Events                                         Avg %Total
~~~~~~~~~~~~~~~~~~                                        wait   Call
Event                                 Waits    Time (s)   (ms)   Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
CPU time                                         32,205          51.0
db file sequential read           5,966,390      11,183      2   17.7 User I/O
SQL*Net break/reset to client         2,597       4,250   1637    6.7 Applicatio 
gc cr grant 2-way                 2,705,303       2,222      1    3.5 Cluster
gc current block 2-way              957,231       1,812      2    2.9 Cluster

Knockout
Desde luego el caso no estaba cerrado, ahora había tiempo para cerciorarse de que esta situación no se volviera a presentar, y por ello era necesario modificar el parámetro MAXLOGHISTORY, mismo que controla qué tan grande puede ser el historial de archived redo logs en el controlfile. Para ello empezamos por obtener un script que nos permitiera reconstruirlo con un valor adecuado:

alter database backup controlfile to trace;

CREATE CONTROLFILE REUSE DATABASE "DB" NORESETLOGS FORCE LOGGING ARCHIVELOG
    MAXLOGFILES 51
    MAXLOGMEMBERS 3
    MAXDATAFILES 200
    MAXINSTANCES 8
    MAXLOGHISTORY 29200
LOGFILE
  GROUP 11 '+DG1/db/onlinelog/group_11.439.755028947' 
           SIZE 800M BLOCKSIZE 512,
  GROUP 12 '+DG1/db/onlinelog/group_12.1143.755028957'
           SIZE 800M BLOCKSIZE 512,
  GROUP 13 '+DG1/db/onlinelog/group_13.1170.755028963' 
           SIZE 800M BLOCKSIZE 512,
. . .

Modificamos el valor 29200 por 5000, y en la fecha ya programada para tal fin detuvimos la base de datos, ejecutamos el script de reconstrucción del controlfile y reiniciamos los servicios. Como existía también un physical standby tuvimos que crear y transferir un nuevo standby controlfile, con lo que finalmente pudimos decir con toda confianza: ¡caso cerrado!

Posts Relacionados:
Siga leyendo >>

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

sábado, 17 de mayo de 2014

Troubleshoot: optimizador confundido

Unos días atrás me reportaron un problema de mal desempeño de una aplicación bancaria. Resulta que si bien el número de transacciones no era alto, el valor monetario si lo era, por lo que era prioritario que se completase casi instantáneamente. Con el pasar del tiempo estas transacciones iban demorando más y más, al punto de que eventualmente alguna de ellas era dada por fallida y debía ser reiniciada, poniendo nerviosos a todos los involucrados en el negocio, y es en este escenario que deciden acudir a mi asesoría.

El primer problema que encontré es que la aplicación no estaba instrumentada y por tanto su código se confunde con el de otras aplicaciones que también se ejecutan en esa instancia. Afortunadamente, de entre todo el universo de SQLs, el DBA había ya identificado un par de sentencias, y que coincidentemente figuraban en los reportes AWR como las principales responsables de buffer gets, por lo que de inmediato procedí a analizarlas.

select nvl(max(event_seq_no), 0) 
  from cstbs_contract_change_log 
 where contract_ref_no = :b1
---------------------------------------------------------------------
| Id  | Operation                   | Name                          |
---------------------------------------------------------------------
|   0 | SELECT STATEMENT            |                               |
|   1 |  SORT AGGREGATE             |                               |
|   2 |   FIRST ROW                 |                               |
|   3 |    INDEX FULL SCAN (MIN/MAX)| PK01_CSTB_CONTRACT_CHANGE_LOG |
---------------------------------------------------------------------

select nvl(max(event_seq_no), 0) 
  from istbs_contractis 
 where contract_ref_no = :b1
------------------------------------------------------------
| Id  | Operation                   | Name                 |
------------------------------------------------------------
|   0 | SELECT STATEMENT            |                      |
|   1 |  SORT AGGREGATE             |                      |
|   2 |   FIRST ROW                 |                      |
|   3 |    INDEX FULL SCAN (MIN/MAX)| PK01_ISTB_CONTRACTIS |
------------------------------------------------------------

Se comprobó que para ambas tablas existían índices por la columna contract_ref_no, que eran desde luego mucho más adecuados que los de clave primaria, pero por alguna razón el Optimizador no los estaba tomando en cuenta, por lo que como medida inicial se procedió a generar nuevas estadísticas, con la esperanza de que eso fuese suficiente para que el Optimizador tomara la decisión correcta.

exec dbms_stats.gather_table_stats( 
   ownname => 'FCCPRD', 
   tabname => 'CSTB_CONTRACT_CHANGE_LOG'
   cascade => TRUE, 
   estimate_percent => 100, 
   method_opt => 'FOR ALL INDEXED COLUMNS SIZE AUTO' );

exec dbms_stats.gather_table_stats( 
   ownname => 'FCCPRD', 
   tabname => 'ISTB_CONTRACTIS'
   cascade => TRUE, 
   estimate_percent => 100, 
   method_opt => 'FOR ALL INDEXED COLUMNS SIZE AUTO' );

Sin embargo los planes de ejecución permanecieron intactos, por lo que como segunda medida, y considerando que se trataba de Oracle Server 10.2.0.4, se procedió a asignar SQL Profiles. Para la primera sentencia se logró obtenerlo mediante el uso de SQL Advisor, pero para la segunda sentencia no fue posible, siendo necesario recurrir al procedimiento señalado en el Note 1400903.1 How to use hints to customize SQL Profile or SQL PLAN Baseline. Luego de esto se obtuvieron finalmente los planes eficientes para ambas sentencias SQL.

----------------------------------------------------------------------
| Id  | Operation                    | Name                          |
----------------------------------------------------------------------
|   0 | SELECT STATEMENT             |                               |
|   1 |  SORT AGGREGATE              |                               |
|   2 |   TABLE ACCESS BY INDEX ROWID| CSTB_CONTRACT_CHANGE_LOG      |
|*  3 |    INDEX RANGE SCAN          | IX03_CSTB_CONTRACT_CHANGE_LOG |
----------------------------------------------------------------------

--------------------------------------------------------------
| Id  | Operation                    | Name                  |
--------------------------------------------------------------
|   0 | SELECT STATEMENT             |                       |
|   1 |  SORT AGGREGATE              |                       |
|   2 |   TABLE ACCESS BY INDEX ROWID| ISTB_CONTRACTIS       |
|*  3 |    INDEX RANGE SCAN          | IX03_ ISTB_CONTRACTIS |
--------------------------------------------------------------

Con esto los tiempos de ejecución se redujeron notablemente, de un valor inicial promedio de 34.2" a solo 8.7", pero aun así quedaba la percepción de que la transacción podía ser más rápida aun, por lo que era inevitable instrumentar la aplicación y así poder identificar con precisión las sentencias SQL adicionales que pudiesen ser afinadas. Para ello se incorporaron las siguientes líneas de código en la rutina problemática:

create or replace PACKAGE BODY pks_msg_router AS
. . .
  PROCEDURE p_process_req_msg  (is_req_clob    IN   VARCHAR2
  . . .
  BEGIN
    -- Inicio de la instrumentación
    dbms_application_info.set_module(
      module_name => 'msg_router',
      action_name => 'process_req_msg');
    . . .
    
    . . . 
    -- Fin de la instrumentación
    dbms_application_info.set_module(
      module_name => NULL,
      action_name => NULL);
  END p_process_req_msg;
. . .

Luego de ser implementado el cambio se pudieron identificar más sentencias SQL ineficientes, como por ejemplo:

select nvl(max(event_seq_no),0) from cstbs_contract_event_log 
where contract_ref_no = :b1
--------------------------------------------------------------------
| Id  | Operation                   | Name                         |
--------------------------------------------------------------------
|   0 | SELECT STATEMENT            |                              |
|   1 |  SORT AGGREGATE             |                              |
|   2 |   FIRST ROW                 |                              |
|   3 |    INDEX FULL SCAN (MIN/MAX)| PK01_CSTB_CONTRACT_EVENT_LOG |
--------------------------------------------------------------------

select nvl(max(change_seq_no),0) from cstbs_contract_change_log 
where contract_ref_no = :b2 and event_seq_no = :b1
----------------------------------------------------------------------
| Id  | Operation                    | Name                          |
----------------------------------------------------------------------
|   0 | SELECT STATEMENT             |                               |
|   1 |  SORT AGGREGATE              |                               |
|   2 |   FIRST ROW                  |                               |
|   3 |    INDEX RANGE SCAN (MIN/MAX)| PK01_CSTB_CONTRACT_CHANGE_LOG |
----------------------------------------------------------------------

Lo extendido del problema termina por confirmar que no se trata de una situación normal, sino que se trataría de la incidencia de un bug a nivel del Optimizador, siendo el común denominador a todas estas sentencias el que incluyen el operador MIN y/o MAX, y es justamente este criterio el que empleamos para hacer una búsqueda en My Oracle Support, encontrando lo siguiente:

Bug 8467123 : POOR PERFORMANCE OF QUERY WITH INDEX FULL SCAN (MIN/MAX)
Bug 11834402 : CBO CHOOSES A SLOW INDEX FULL SCAN (MIN/MAX) OVER A MUCH FASTER INDEX RANGE SCAN
Bug 9140303 : OPTIMIZER CHOOSE WRONG INDEX FOR MIN/MAX SQL
Bug 8323407  "INDEX RANGE SCAN (MIN/MAX)" Cost change

Al parecer Oracle introdujo en Oracle Server 10.2.0.4 un fix para el bug 5611962 CBO does not use index full scan (MIN/MAX) with part. range iterator, pero este fix terminó generando un nuevo bug. ¿La solución? Hacer upgrade a 10.2.0.5 o superior, pero no era viable en este escenario ya que tomaría algo de tiempo en implementar. Afortunadamente existe un workaround: ¡deshabilitar el fix!

SQL> alter system set "_fix_control" = "5611962:OFF";

Luego de realizar pruebas preliminares se concluye que el workaround es efectivo, programándose su aplicación a nivel de toda la instancia. Luego de ello se vuelve a analizar el universo de sentencias SQL de la transacción problemática, encontrándose que las sentencias previamente identificadas se ejecutan ahora eficientemente, con nuevos planes de ejecución.

(1) Situación original                              34.2"
(2) Luego de aplicar SQL Profile (2 SQLs)            8.7"
(3) Luego de deshabilitar fix del BUG 5611962        0.8"

Con estos resultados se dio por concluido el afinamiento de la aplicación, obteniendo una disminución del tiempo de ejecución en nada menos que un ¡98%! A la fecha la aplicación opera normalmente y los usuarios están contentos con el tiempo de respuesta, por lo que se considera un caso más resuelto satisfactoriamente.

Espero que se hayan entretenido con la resolución de este caso de la vida real. ¡Será hasta la próxima amigos!

Posts Relacionados:
Siga leyendo >>

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

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:
Siga leyendo >>

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

viernes, 26 de octubre de 2012

¿Cómo mover ocr y vdisk a nuevo disk array?

No hace mucho, uno de mis clientes inició el proceso de migración de su disk storage system, desde EMC CX4 hacia EMC VNX. Ellos tienen sus bases de datos operando con Oracle RAC 11.2.0.3, por lo que siguieron el procedimiento de agregar LUNs del nuevo EMC VNX en los diskgroups de datos, para luego retirar los LUNs del antiguo EMC CX4, aprovechando el rebalanceo automático que hace ASM al agregarle y removerle discos. Hasta aquí todo bien, pero quedaba el trabajo sobre el diskgroup que contiene el ocr, voting disks y spfile de ASM, llamado en este caso OCR, para el cual el procedimiento no es tan simple como agregar y retirar discos. A continuación les mostraré en detalle el procedimiento que seguí para concluir con este último paso en la migración de disk storage system para este diskgroup, cumpliendo el requerimiento expreso del cliente: no suspender el servicio.

Empezaré por mostrarles el escenario sobre el cual se trabajó:


El diskgroup OCR fue creado con redundancia normal, por lo cual es requisito obligatorio emplear 3 discos. El objetivo es que sus contenidos sean ahora trasladados a 3 discos en el nuevo disk array, pero no se puede hacer directamente como en el caso de un diskgroup de datos, básicamente debido a los voting disk.

El ocr y el spfile de ASM son archivos que se distribuyen entre los discos que constituyen el diskgroup sobre el cual residen, pero Oracle crea un voting disk idéntico en cada disco del diskgroup. Así, al agregar mas discos al diskgroup, el ocr y el spfile son candidatos a ser redistribuidos entre todos los discos, pero los voting disk no, se quedan en sus discos originales, por lo que requieren de un tratamiento especial.

El Note 428681.1, OCR / Vote disk Maintenance Operations: (ADD/REMOVE/REPLACE/MOVE), tiene el detalle de lo que sebe hacer en diversos escenarios, de cuya lectura queda claro que no es posible agregar mas voting disks, sino solamente moverlos a otro diskgroup. Por esta razón se solicitó la creación de 3 nuevos LUNs, sobre los cuales se crearía el diskgroup que albergaría temporalmente a los voting disk, de forma que quedara algo así:


Luego que los LUNs estuvieron provisionados y debidamente asignados a todos los nodos del RAC, se procedió a la creación del diskgroup VDISK, mediante el utilitario ASMCA.



Con esto ya estamos listos para el paso inicial: el movimiento de voting disks.

[oracle@rac1]$ crsctl query css votedisk
##  STATE    File Universal Id                File Name Disk group
--  -----    -----------------                --------- ---------
 1. ONLINE   1e56372cc94a4f92bfd9952beef36a5b (/dev/rhdiskpower3) [OCR]
 2. ONLINE   570dd695f7ea4f08bf86d92adc2a2343 (/dev/rhdiskpower1) [OCR]
 3. ONLINE   027f719d79914f72bfc1fdfb3098209b (/dev/rhdiskpower2) [OCR]
Located 3 voting disk(s).

[oracle@rac1]$ crsctl replace votedisk +VDISK
Successful addition of voting disk 42cd3a1355714febbf8b8be58da5d277.
Successful addition of voting disk 95b0b904a7844f6bbf35881a7fd545f6.
Successful addition of voting disk 189d6f4cba754fc6bf1d8f94fd70fe89.
Successful deletion of voting disk 1e56372cc94a4f92bfd9952beef36a5b.
Successful deletion of voting disk 570dd695f7ea4f08bf86d92adc2a2343.
Successful deletion of voting disk 027f719d79914f72bfc1fdfb3098209b.
Successfully replaced voting disk group with +VDISK.
CRS-4266: Voting file(s) successfully replaced

[oracle@rac1]$ crsctl query css votedisk
##  STATE    File Universal Id                File Name Disk group
--  -----    -----------------                --------- ---------
 1. ONLINE   42cd3a1355714febbf8b8be58da5d277 (/dev/rhdiskpower57) [VDISK]
 2. ONLINE   95b0b904a7844f6bbf35881a7fd545f6 (/dev/rhdiskpower130) [VDISK]
 3. ONLINE   189d6f4cba754fc6bf1d8f94fd70fe89 (/dev/rhdiskpower90) [VDISK]
Located 3 voting disk(s).

Ayudados con el utilitario crsctl, hemos trasladado los voting disks desde el diskgroup OCR hacia el diskgroup VDISK, siendo el escenario actual:


Ahora que el diskgroup OCR contiene solamente el ocr y el spfile de ASM, ya es posible recurrir al rebalanceo de ASM, por lo que procedemos a agregarle los LUNs provisionados en el disk array nuevo, empleando nuevamente el utilitario ASMCA.



Luego de agregar los 3 LUNs del nuevo disk array, la configuración es:


Ahora ya es posible retirar los discos del disk array antiguo, siempre apoyados con ASMCA.



Con los LUNs antiguos ya removidos, la nueva situación es:


Ahora que los contenidos del diskgroup OCR residen exclusivamente sobre LUNs del nuevo array disk, es hora de retornar los voting disks a su diskgroup original.

[oracle@rac1]$ crsctl replace votedisk +OCR
Successful addition of voting disk 5385fdac3eb44f96bf206fc7cce7fe48.
Successful addition of voting disk a4a5d6afbd064fa2bffe306654b0f3ac.
Successful addition of voting disk 2cbc13a0ff444fd7bf79670b75fe42c4.
Successful deletion of voting disk 42cd3a1355714febbf8b8be58da5d277.
Successful deletion of voting disk 95b0b904a7844f6bbf35881a7fd545f6.
Successful deletion of voting disk 189d6f4cba754fc6bf1d8f94fd70fe89.
Successfully replaced voting disk group with +OCR.
CRS-4266: Voting file(s) successfully replaced

[oracle@rac1]$ crsctl query css votedisk
##  STATE    File Universal Id                File Name Disk group
--  -----    -----------------                --------- ---------
 1. ONLINE   5385fdac3eb44f96bf206fc7cce7fe48 (/dev/rhdiskpower1002) [OCR]
 2. ONLINE   a4a5d6afbd064fa2bffe306654b0f3ac (/dev/rhdiskpower1001) [OCR]
 3. ONLINE   2cbc13a0ff444fd7bf79670b75fe42c4 (/dev/rhdiskpower1000) [OCR]
Located 3 voting disk(s).

Finalmente hemos llegado al siguiente escenario:


En este momento ya tenemos tanto el ocr, el spfile y los voting disks en el diskgroup OCR, usando únicamente LUNs del nuevo disk storage system EMC VNX, por lo que es posible eliminar el diskgroup VDISK, ya no necesitamos más de él.



Con esto podemos dar por concluida la tarea de movimiento de los contenidos del diskgroup OCR (ocr, voting disks, spfile de ASM), hacia el nuevo disk array EMC VNX, sin suspensión alguna del servicio y en muy pocos minutos. Desde luego, el procedimiento fue previamente probado en un ambiente virtualizado, pues una cosa es lo que dice la documentación y otra la que pasa en la vida real, por lo que es altamente recomendable que Uds. tambien lo hagan, recuerden que cada instalacion tiene su particularidades, así que mejor no correr riesgos innecesarios. Será hasta la próxima amigos!

Post Relacionados:
Siga leyendo >>

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

jueves, 27 de septiembre de 2012

OOW 2012, allá voy!

Cada año se realiza el Oracle Open World, al cual somos cordialmente invitados todos los Oracle ACE. Pero nunca faltaba algún contratiempo (léase proyecto en marcha con plazos ajustados) que me obligaba a postergar mi asistencia, pero al iniciar este año tomé la decisión de asistir sí o sí.

Desde Junio hice la compra de los respectivos boletos de avión, que -gracias a los KM acumulados- me salieron gratis! Y ya que entraba en la onda del low budget, opté por reservar habitación en el Park Hotel de San Francisco, por solo US$450 la semana!, una ganga considerando que en San Francisco no es nada barato el alojamiento, y más aún cuando 50,000 personas llegan de golpe casi el mismo día y pugnan por tener un alojamiento cercano al Moscone Center, lugar donde se desarrolla el OOW, y el Park Plaza está a unas pocas cuadras, tan cerca que puedo llegar incluso a pie.

Resuelto el problema de cómo llegar y dónde alojarme, venía la tarea de escoger entre los cientos de presentaciones disponibles, tarea nada fácil desde luego. Luego de revisar y revisar, terminé seleccionando lo que me pareció más cercano a lo que vengo desarrollando regularmente: Tuning de Base de Datos y Aplicaciones, y soluciones de Alta Disponibilidad y Contingencia.

My Schedule

Aparte de las presentaciones técnicas, Larry Ellison siempre busca robarse el show, y este año no sería la excepción: hay fuertes rumores de que nos daria la sorpresa con el lanzamiento de Oracle 12c Database, nada mal, cruzo los dedos para que así sea.

Y como no todo es Oracle, aprovecharé a tomar una semana de descanso, para conocer las atracciones principales de San Francisco (Alcatráz, Golden Gate) y probablemente San Diego (Zoo, SeaWorld), y por qué no, para deleitarme con un buen cebiche al estilo peruano en La Mar .

Es todo por el momento amigos, prometo mantenerlos al tanto de las novedades en el OOW (siganme en Twitter @enriqueorbegozo) y a mi retorno retomar los Posts técnicos, que buen tiempo he abandonado, hasta la próxima!
Siga leyendo >>

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