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 .75A 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
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/OEste 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: 16146Gotcha!
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 84612SQL> 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 336Top 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 ClusterKnockout
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,
. . .