Statspack

Hola mundo! Bienvenidos a una tarde más de estudio de performance de Oracle SQL, hoy os traigo una pequeña actividad que hice hace unas semanas, para el Master de Optimización de SQL del reconocido DBA Javier Morales, que estoy cursando actualmente (os dejo el enlace para que no os perdais la edición del año que viene: Master Optimización SQL en Oracle).

Al estudiar las herramientas de monitorización y análisis de rendimiento disponibles en Oracle, una de las que merece especial atención es Statspack. Esta herramienta permite recopilar estadísticas de rendimiento y generar informes detallados sobre el comportamiento de la base de datos durante un periodo de tiempo determinado y al no requerir licencias adicionales, puede utilizarse en Standard Edition, lo que la convierte en una alternativa especialmente útil para el análisis de rendimiento en entornos donde herramientas como AWR no están disponibles.

La tarea consistía redactar un pequeño diagnóstico analizando los varios fragmentos de un informe Stackpack, asi sin más, sin contexto, a ciegas, solo tú vs métricas. Por tanto, no es un informe completo ni una auditoria pero nos va a servir para una primera toma de contacto con Stackpack para ver qué significan algunas de sus métricas y que conclusiones podemos deducir de ellas.

Estos informes nos proporcionan la información sobre un periodo en el tiempo, pero el trabajo de análisis y diagnóstico corresponde al DBA. Asique vamos con ello, pero antes, recuerda:

"Paso a paso y los problemas de uno en uno" .

Análisis de Stackpack

1. Información básica

6 horas de ejecución
Elapsed: 360 mins
DB time: 27.96 min → la BD trabajó 27.96 min de las 6 h reales →0.1 av de actives sessions ( 0.077)
Primera conclusión: no ha tenido mucha caga, la base de datos no está estresada.

2. Top 5 timed events

Primero una breve definición de lo que estamos analizando:

CPU time: tiempo que oracle pasó ejecutando activamente código en la cpu, representa el tiempo de trabajo real:
- Ejecución de sentencias SQL, JOINS....
- Parseo
- Ejecuciones de PL/SQL
- Cálculo de planes
log file sync: evento de espera, tras hacer un commit:
- Escribe los redo logs
- Espera confirmacion fisica del disco
- Devuelve control al user
- La sesión está esperando a que el LGWR termine de escribir los redo
direct path read: oracle está leyendo bloques desde disco a la PGA directamente, sin pasar por buffer cache.
- Ampliar conocimiento
db file sequencial read: lectura secuencial de bloques individuales( normalmente implica acceso por índice). Un valor alto puede implicar:
- Nested loops excesivos, índices malo, I/O lento
- SQL ejecutándose millones de veces
- Importante mirar → Average wait
- Tiempos:
  - 0-2 ms : excelente
  - 3-8 ms: normal
  - 10-20 ms: sospechoso
  - >20: storage lento
Disk file operations I/O: oracle espera operaciones físicas sobre archivos, no necesariamente lecturas de tablas. Muy común en RMAN, autoextend, tempfile creciendo, ASM/filesystem lento. Puede involucrar:
- Apertura/cierre de datafiles
- Resize de archivos
- File metadata
- Tempfiles

Resumen:

CPU alta → problemas lógicos (SQL)
Sequencial read alto → problema de acceso a datos
Direct path read alto → queries grandes /full scans
Log files sync alto → problemas de commit/ redo
Disk file operation i/o → problema infra/storage

Ahora interpretamos los parámetros que acompañan a los eventos

Waits: cantidad de veces que oracle tuve que esperar ese evento
Time(S): total tiempo acumulado esperando ese evento ( tiempo total perdido)
Avgs wait(ms) : tiempo promedio que oracle tardó en cada spera ( es decir, si el recurso responde rápido o lento)
% total call time: porcentaje del tiempo total de DB Time consumido por ese evento

Volviendo a nuestro informe:

CPU time

Oracle estuvo 878 segundo ejecutando trabajo
Conclusión: 58.6% del db time fue cpu → más de la mitad del tiempo fue trabajo efectivo de oracle, no esperas

Log file sync

241.888 waits → 242mil eventos de redo log escribiéndose en disco para una bd con solo 27.96 mins de DB time
- entonces, no estaba sobrecargada pero algo podría estar dando lugar a un elevado numero de commits, checkpoints, escrituras internas
- conformando el 25.4% del DB Time
Tiempo consumido = 382 s (6.36 s)
Avg: probablemente truncado → 1.58 mins x 241.888 = 382 s
- 2ms para log file sync es bueno
Conclusión: la infra parece estar sana, el problema puede estar en la aplicación.

Direct path read

127 mil operaciones.
Avg wait excelente.
Tiempo consumido 146s (2.4 min)
menos del 10% del tiempo total de oracle
Conclusión: aunque ocurrió con un frecuencia alta, apenas supone el 10% total.

Segunda conclusión general:

DB sana a nivel de infraestructura.
Posibles problemas:
- de lógica SQL
- commints frecuentes
- consultas muy grandes.

3. SQLs de alto impacto

SELECT * FROM ZNOTIFICACIONES

Elapsed time : tiempo total consumido por todas las ejecuciones
- 176.91-32.36 = 144.45s que estuvo esperando
Executions: se ejecutó 108 veces
Elap per exec : cada ejecución tarda 1.64 s
Total: consume el 10.5% del tiempo total
CPU time: solo 32.46 s fueron de cpu
Physical read: lecturas a disco porque no está en buffer cache (valor muy alto)
FECHA_CREACION <= SYSDATE

→ Todo lo creado hasta hoy (probablemente toda la tabla , lo que implicará un Full Scan

→ Sumamos carga al ordenarlo luego por id

Cada vez que se lanza está leyendo casi 58,633.5 bloques
- Cada bloque ≃ 8KB → 58.633 bloques x 8KB = aprox 469 MB por ejecución
Physical Reads totales ≃ 6.332.423 x 8 kb ≃ 48 GB leídos en disco
Conclusión: 48 GB leídos en disco, excesivo para una select sobre una tabla

DETELE FROM SINCRTMP

Executions: número muy elevado de ejecuciones
- 31900 veces ejecutada cada hora →532 veces cada minuto → se puede estar ejecutando en bucle
Buffer Gets: lecturas lógicas altísimas
Gets per executioin → muy alto para borrado usando una clave
Elapsed time: unos casi 25 min, mucho tiempo
- Se ejecuta 191.857 veces y cada ejecución lee aproximadamente 1.919 bloques lógicos
- Tiempo medio de ejecución: 1490.41s / 191.857 = aprox 0.0078s ( 8 ms)
  - 8 ms x 191.857 veces = aprox 1534s (aprox el elapsed time, casi 25 min )
Tiempo medio de ejecución: 1490.41s / 191.857 = aprox 0.0078s ( 8 ms)
- 8 ms x 191.857 veces = aprox 1534s (aprox el elapsd time,casi 25 min)

Buffer gets son bloques leídos en memoria, desde buffer cache. No implican disco, pero sí implican trabajo lógico de oracle:

Buscar bloques
Recorrer índices
Comprobar filas

Conclusión: muy probable Oracle está haciendo un Full Scan para cada delete → problema con el índice, quizás mal definido/inexistente ??

Soluciones:

Comprimir la tabla.
Crear un índice por clave.
Analizar si es posibles reducir esas 191.857 ejecuciones con un sleep para bajar la frecuencia con la que se ejecuta, una vez por minuto por ejemplo, en vez de cada 8 ms.

Análisis de segmentos

Que porcentaje de todas las lecturas lógicas de la bd pertenece a ese objeto.

Los logical reads (buffer gets):

Bloques leídos desde buffer cache
Accesos lógicos en memoria oracle

Conclusiones:
- Las ejecuciones sobre la tabla ZNOTIFICACIONES genera el 93.9 % de todas las lecturas físicas de la instancia
- Logical reads = 3.219.424 ≃ Physical Reads= 3.218.456

→ prácticamente cada lectura lógica ha implicado una lectura física a disco

→no está usando bloques en caché

SELECT…. INNER JOIN….

CPU TIME ≈ Elapsed → la query no espera, consume CPU principalmente
Ese 36.6% es sobre el trabajo efectivo, esos 27 minutos totales de la bd
Gets per Exec demasiado alta para una select con filtros

Lo que podemos deducir:

En cada ejecución leemos esos 2.147 bloques, es decir, nos lo estamos trayendo todo prácticamente en cada ejecución
la ZSD puede ser una vista
JOIN en el que probablemente no coincidan FK con PK
JOIN transformada para que encaje bien
Se estań completando los valores con 0
Conclusión: no parece un problema de disco ni esperas, puede ser un problema con las columnas que se utilizan para hacer el join y los filtros.