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:
Entradas
