Caso 2: sesión dominada por espera de I/O

El caso 2 es una sesión de 17 min 9 s en la que la clase User I/O suma el 51,4% del tiempo y las 323.268 lecturas de bloque único, el 35,6%. Esta página recorre el informe del caso 2 en el orden de las secciones, del resumen a los objetos, hasta la causa probable y qué hacer. El caso muestra por qué encontrar la sentencia antes de acelerar el disco, y qué hacer cuando la sentencia más pesada no tiene plan en el trace.

Paso 1: resumen y aviso

Antes del Resumen, el informe muestra el aviso 299276 llamadas recursivas sin llamada de nivel 0 correspondiente (trace iniciado o cortado en medio de una llamada). El Resumen trae:

• Tiempo total: 1.029,051 s, o 17 min 9 s;
• Llamadas a la base de datos: 305.623, 180 de nivel 0;
• Esperas: 341.608, con 75,177 s entre llamadas;
• Sentencias distintas: 185, con 65 commits.

Casi todo el trabajo es SQL recursivo (SQL recursivo), y el trace registró las esperas. En Llamadas de nivel 0 más largas, la más larga dura 0,044 s: ninguna llamada de la aplicación explica 17 minutos. En la misma tabla, a 74,823 s del inicio, aparece el PARSE de la sentencia #53, un bloque PL/SQL anónimo (DECLARE ... BEGIN ... END;) que llama a rutinas de paquetes. En el detalle de la #53, el cuadro Llamadas solo tiene ese PARSE: el EXEC del bloque no está en el archivo, porque todavía se ejecutaba cuando el fragmento termina (líneas del trace).

El trace tiene, entonces, dos fases: unos 75 s de llamadas cortas de la aplicación y unos 954 s dentro del bloque #53, hasta el final del archivo.

Véalo en el informe: Resumen del caso 2. Para leerlo: Resumen y Llamadas de nivel 0 más largas.

Paso 2: diagnóstico

El Diagnóstico trae cuatro hallazgos:

El primer hallazgo pide mirar el plan antes que el disco, y el enlace Ver distribución de latencia lleva a la prueba (paso 7). El bucle de la #1 y la #2 existe, pero las dos suman el 1,3% del tiempo: corregirlas ahora no cambia el caso. Los hallazgos no dicen qué sentencia hace las lecturas: la que más gasta, la #5, no tiene plan en el fragmento, y sin plan no hay hallazgo de plan para ella (paso 6). El perfil y las sentencias muestran el tamaño de cada cosa.

Véalo en el informe: Diagnóstico del caso 2. Para leerlo: Diagnóstico.

Paso 3: perfil

El Perfil del tiempo de respuesta divide los 1.029,051 s en componentes. Los mayores:

Por clase de espera, User I/O suma el 51,4%, No contabilizado el 23,0%, CPU el 18,3% e Idle el 7,3%. Lo que el perfil sostiene y lo que descarta:

• Disco lento: fuera como causa principal. La media es de 1,132 ms por lectura: el almacenamiento responde rápido, y el tiempo viene de la cantidad, 323.268 lecturas (lectura lenta). El paso 7 lo confirma por la distribución.
• Tiempo en la aplicación: solo en la primera fase. Los 74,696 s de SQL*Net message from client caben en los 74,8 s antes del bloque #53. Es tiempo fuera de la base de datos, que el ajuste de SQL no reduce, y no es la parte lenta del caso (sesión esperando a la aplicación).
• Una llamada pesada, y no muchas. El máximo de 104,206 s de CPU en una llamada EXEC muestra que una sentencia concentra el trabajo. El paso 4 dice cuál.
• Tiempo no contabilizado: revise el servidor. Los 149,483 s dentro de las llamadas son tiempo en que la sesión no estaba en la CPU ni en una espera registrada, y una causa común es la cola de CPU (dentro de las llamadas). Los 87,678 s entre llamadas son, como en el caso 1, tiempo del bloque entre un SQL y otro (entre llamadas).

Véalo en el informe: Perfil del caso 2, con las filas db file sequential read y SQL*Net message from client. Para leerlo: Perfil del tiempo de respuesta y Clases de espera y SQL recursivo.

Paso 4: sentencias principales

En Sentencias principales por componente y por clase, la misma sentencia aparece arriba en casi todos los grupos: la #5, un SELECT que empieza con WITH TAB_0082 AS (SELECT DISTINCT.

La segunda es la #7, DELETE FROM TAB_0049 A WHERE A.COL_0086 = :B1, con 55,010 s de CPU de EXEC (el 32,3% del componente) y 41,699 s de tiempo no contabilizado dentro de las llamadas (el 27,9%).

En Sentencias SQL por contribución, la #5 tiene una contribución de 0,587 s, pero un Inclusivo de 740,853 s: el 72,0% del tiempo total en una única sentencia. La lista ordena por contribución, y por eso queda detrás de cuatro sentencias que, juntas, suman menos de 21 s de inclusivo. La #5 tiene profundidad 2, Exec 1, Fetch 126 y 63.000 filas, con 7.669.408 lecturas lógicas (LIO) y 3.528.057 bloques leídos del disco (PIO). La #7 tiene un Inclusivo de 102,905 s, el 10,0% del total, y borró 2.953.545 filas en una ejecución. Como en el caso 1, la contribución no sirve para ordenar: el bloque #53 no se cierra en el archivo, y Tiempo no atribuido a ninguna sentencia suma 1.017,699 s. Compare por el inclusivo.

Véalo en el informe: Sentencias por componente del caso 2 y Sentencias SQL del caso 2. Para leerlo: Sentencias por componente y Sentencias SQL por contribución.

Paso 5: detalle de la sentencia

En el detalle de la #5, Peso en el tiempo total es 0,587 s e Inclusivo, 740,853 s, con Profundidad 2, SQL recursivo: la sentencia se ejecuta para atender a un SQL de profundidad 1, dentro del bloque. El cuadro Llamadas muestra dónde está el tiempo:

Casi todo el tiempo está en la única llamada EXEC: 688,659 s antes de que el primer FETCH devuelva filas. Las 63.000 filas salen en 126 FETCH, una media de 500 por FETCH: la rutina ya busca las filas en lote. Son unas 122 lecturas lógicas y 56 bloques del disco por cada fila devuelta: la consulta lee mucho más de lo que devuelve.

El Perfil de la sentencia suma 364,191 s de db file sequential read en 322.865 lecturas, 104,206 s de CPU de EXEC, 98,163 s de tiempo no contabilizado, 82,616 s de direct path read y 62,222 s de lectura y escritura en TEMP. Son tres tipos de trabajo: lectura bloque a bloque, típica de acceso por índice y por ROWID; lectura directa de un segmento grande; y ordenación o hash que no cupo en memoria.

Véalo en el informe: detalle de la sentencia #5. Para leerlo: Detalle de la sentencia.

Paso 6: plan

El detalle de la #5 no tiene el bloque Plan de ejecución, y el cuadro Llamadas no tiene CLOSE: el cursor todavía estaba abierto al final del fragmento. El plan sale de las líneas STAT, que el trace trae cuando el cursor se cierra (guía de tracing de 19c). Sin el CLOSE, las líneas STAT de la #5 no llegaron al archivo.

Obtenga el plan en la base de datos, mientras el cursor siga en la cursor cache, con el sql_id del título del detalle (en el caso 2, d7sadnr6zu6k9):

select *
  from table(dbms_xplan.display_cursor('&sql_id', null, 'ALLSTATS LAST'));

Las filas y las lecturas reales de cada operación solo aparecen si la ejecución recolectó las estadísticas del plan, con la sugerencia GATHER_PLAN_STATISTICS o con STATISTICS_LEVEL en ALL en la sesión; sin eso, el plan trae solo las estimaciones (referencia de DBMS_XPLAN). En el plan, busque la operación con más lecturas y compruebe cuántas veces se ejecuta y cuántas filas devuelve, como en el plan del informe.

El plan de la #7 está en el fragmento. La operación 1, DELETE TAB_0049, tiene el 98,1% del tiempo del plan y el destacado Escribió 66.842 bloques en TEMP: la workarea de la PGA no alcanzó. La operación 2, INDEX RANGE SCAN IDX_0034, devolvió 2.953.545 filas para 2.943.270 estimadas: la estimación es correcta, así que el problema no es de estadísticas (estimación de filas errónea). En el cuadro Llamadas, el único EXEC dura 102,905 s, con 55,010 s de CPU y 13.153.243 lecturas en Actual (CU), el modo de quien modifica datos (cu). El costo está en borrar casi 3 millones de filas, y no en encontrarlas: el índice tardó 1,952 s.

Véalo en el informe: operación 1 del plan de la #7. Para leerlo: operación que concentra el plan.

Paso 7: esperas y latencia

En Distribución de latencia, el db file sequential read muestra 271.109 lecturas por debajo de 1 ms (83,9%), que suman 99,938 s; 47.699 de 1 a 10 ms, con 186,767 s; y 4.460 por encima de 10 ms, con 79,162 s. La mayoría de las lecturas es rápida, y solo la parte rápida ya suma 99,9 s: reducir la cantidad rinde más que acelerar el disco. Vale la pena llevar la cola por encima de 10 ms al equipo de almacenamiento, como punto secundario.

En Lecturas, la tabla Primera lectura y relectura del mismo bloque muestra 323.225 bloques distintos y solo 43 relecturas. No es una buffer cache pequeña que obliga a leer el mismo bloque de nuevo: es el plan visitando 323.000 bloques diferentes, uno por vez.

En Tipos de llamada, son 394 PARSE para 102.658 EXEC: al contrario del caso 1, la rutina mantiene los cursores abiertos, y el parse no es un problema aquí.

Véalo en el informe: latencia del db file sequential read, Lecturas y Tipos de llamada. Para leerlo: Distribución de latencia, Lecturas y Tipos de llamada.

Paso 8: objetos

Objetos con más tiempo de espera empieza por el objeto 192892, sin nombre, con 404,790 s en 290.860 esperas, el 39,3% del tiempo total. Después vienen el 202849, con 66,670 s en 33.428 lecturas de bloque único, y el 192893, con 15,837 s. Por el paso 4, son objetos que lee la #5: tiene el 99,5% del tiempo de db file sequential read y todo el direct path read.

No tienen nombre porque el nombre sale de las líneas STAT, y la #5 no tiene las suyas en el fragmento. Identifique los objetos en la base de datos del trace por el object_id:

select owner, object_name, subobject_name, object_type
  from dba_objects
 where object_id in (192892, 202849, 192893);

En la consola, el obj# abre la página del objeto, con esa consulta y las de columnas, índices y estadísticas (página del objeto). Con el nombre de los objetos y el plan del paso 6, usted sabe qué tabla o índice lee la #5 bloque a bloque.

Véalo en el informe: Objetos del caso 2.

Lo que el fragmento no muestra

El fragmento de 2.000.000 líneas cubre 17 min 9 s de esta sesión. Lo que queda fuera:

• El final de la rutina. El bloque #53 no termina en el archivo: los 17 min 9 s son unos 75 s antes del bloque y unos 954 s dentro de él, y la duración de la rutina entera queda desconocida.
• El plan de la #5 y el nombre de los objetos. Las líneas STAT de la sentencia más pesada no llegaron al archivo (pasos 6 y 8).
• El resto de la regrabación. La #7 borró 2.953.545 filas de TAB_0049, y la #4 grabó en la misma tabla 52.500 filas en 35 ejecuciones. Si la rutina vuelve a grabar lo que borró, el fragmento muestra solo el comienzo de esa fase, y la rutina entera tarda bastante más.
• La contribución de cada sentencia. Con el bloque abierto, compare por el Inclusivo (paso 4).

Para medir la rutina entera, active el trace antes de la llamada y desactívelo después del final, sin límite de tamaño en el archivo (trace cortado a la mitad). Los demás límites de un trace están en lo que WaitScope no hace.

Causa raíz probable

La rutina que llama el bloque #53 gasta el 72,0% del fragmento en una consulta, la #5, ejecutada una vez. Para devolver 63.000 filas, lee 3.528.057 bloques del disco: 322.865 uno a uno, rápidos, en un acceso típico de índice y ROWID, además de lecturas directas de un segmento grande y ordenaciones que van a TEMP. El disco responde rápido; el problema es el volumen que lee el plan. El segundo punto es la #7, que borra 2.953.545 filas en una ejecución y se lleva el 10,0% del tiempo. El bucle de la #1 y la #2 existe, pero pesa el 1,3%.

Lo que no es la causa: disco lento (media de 1,132 ms por lectura), buffer cache pequeña (43 relecturas), parse (394 PARSE) y estimación errónea en el DELETE (2.953.545 filas para 2.943.270 estimadas).

Qué hacer

En la base de datos

1. Obtenga el plan de la #5 con DBMS_XPLAN.DISPLAY_CURSOR (paso 6) e identifique los objetos 192892, 202849 y 192893 (paso 8).
2. En la página de cada objeto, en la consola, revise los índices y las estadísticas de las tablas que el plan lee bloque a bloque: un índice que no atiende el filtro, o estadísticas viejas que llevan al optimizador a acceder por índice a muchas filas (muchas lecturas).
3. Revise la carga de CPU del servidor en el período: los 149,483 s no contabilizados dentro de las llamadas, casi todos en la #5 y la #7, pueden ser cola de CPU (tiempo no contabilizado dentro de las llamadas).
4. Si, con menos filas llegando a las ordenaciones, la #5 y la #7 siguen escribiendo en TEMP, evalúe la memoria de las workareas, por pga_aggregate_target (operación que concentra el plan).
5. Lleve al equipo de almacenamiento las 4.460 lecturas por encima de 10 ms, como punto secundario.

En la aplicación

1. Con el plan en la mano, reescriba la #5 para llegar a las 63.000 filas sin visitar millones de bloques: el filtro más selectivo primero, con un índice que lo atienda, y HASH JOIN en lugar de NESTED LOOPS si el plan muestra acceso por índice sobre muchas filas.
2. Revise el par DELETE e INSERT en TAB_0049. Si la mayor parte de las 2.953.545 filas no cambia de una ejecución a otra, modifique solo lo que cambió, por ejemplo con MERGE, en lugar de borrar y grabar todo de nuevo.
3. Después de lo principal, una las consultas #1 y #2, con 44.591 y 44.590 ejecuciones, al SQL que las alimenta, en lugar de una consulta por fila (fila a fila en PL/SQL).

Cómo confirmar

Genere un trace de la rutina entera, con esperas, antes y después del cambio (activar el trace con DBMS_MONITOR). Compare el Tiempo total, las Ocurrencias de db file sequential read en el perfil y la columna PIO de la sentencia en Sentencias SQL; el hallazgo de muchas lecturas debe desaparecer. En la primera ejecución después del cambio, parte de los bloques puede venir del disco por no estar todavía en la caché: compare mediciones hechas en la misma condición (el método).