All Things Oracle

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 es 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 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 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 dbcntg.
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 la nota 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

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

Agregue un comentario

Su dirección de correo no se hará público. Los campos requeridos están marcados *

Este sitio usa Akismet para reducir el spam. Aprende cómo se procesan los datos de tus comentarios.

Posts Relacionados

Articulo publicado en ToadWorld, sobre cómo superar la falta de archived logs para sincronizar un standby.
Si el optimizador escoge planes de ejecucion ineficientes en queries que usan MAX o MIN, es posible que se trate del bug 5611962.
Qué hacer si nos topamos con el error ORA-600 [kcrf_resilver_log_1] u ORA-600 [4193].

¿Necesitas Ayuda?

Completa estos datos y estaré en contacto a la brevedad.