Caso 1: tiempo entre llamadas y SQL fila a fila

El caso 1 es una sesión de 50,8 s en la que el 73,6% del tiempo queda entre las llamadas, sin espera registrada, y dos sentencias recursivas se ejecutan 89.112 veces cada una. Esta página recorre el informe del caso 1 en el orden de las secciones, del resumen a los objetos: qué muestra cada número, qué hipótesis sostiene o descarta y qué revisar después, hasta la causa probable y qué hacer.

Paso 1: resumen y aviso

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

• Tiempo total: 50,833 s;
• Llamadas a la base de datos: 719.114, solo 6 de nivel 0;
• Esperas: 20.320, con 0,166 s entre llamadas;
• Sentencias distintas: 1.977, con 2 commits.

Casi todas las llamadas son SQL recursivo, el SQL que se ejecuta dentro de PL/SQL, y no pedidos directos de la aplicación (SQL recursivo). Las 20.320 esperas muestran que el trace registró las esperas: el tiempo no contabilizado de este caso no viene de un trace sin esperas. El aviso dice que alguna llamada de nivel 0 empezó antes del archivo o termina después de él.

Para saber cuál, abra Llamadas de nivel 0 más largas: son solo 6 llamadas, y la más larga dura 0,070 s. Es el PARSE de la sentencia #4, el bloque BEGIN ROT_0001('***',*** ); END;, que empieza a 0,068 s del inicio. En Sentencias SQL, la #4 tiene Exec 0. La línea de una llamada solo llega al trace cuando la llamada termina (líneas del trace): el EXEC del bloque todavía se ejecutaba cuando el fragmento termina. Después del PARSE, casi todo el tiempo del caso, unos 50,7 s, transcurre dentro de ese bloque.

Véalo en el informe: Resumen del caso 1. Para leer cada número: Resumen y Llamadas de nivel 0 más largas.

Paso 2: diagnóstico

El Diagnóstico trae nueve hallazgos, en orden de gravedad. Los que se repiten para la #1 y la #2 están en una sola fila:

Los hallazgos son pistas, no conclusiones (Diagnóstico). Los dos primeros hablan del mismo tiempo, 37,419 s. El texto de los huecos sugiere un trace activado y desactivado en medio de la sesión, o un proceso detenido fuera de la base de datos. El paso 1 explica por qué ese tiempo aparece entre llamadas: sin el EXEC del bloque en el archivo, el tiempo que el bloque pasa fuera de las sentencias SQL no cae en ninguna llamada. El tiempo en sí es real: la sesión pasó esos 37,419 s dentro de la rutina, entre un SQL y el siguiente. Los demás hallazgos señalan las sentencias que ella ejecuta: dos SELECT una vez por fila, cada uno con un PARSE por ejecución, e INSERT con literales.

Véalo en el informe: Diagnóstico del caso 1.

Paso 3: perfil

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

Por clase de espera, No contabilizado suma el 73,7%, CPU el 23,8% y User I/O el 2,4%. El perfil descarta tres hipótesis:

• Tiempo en la aplicación. Cuando la aplicación tarda entre un pedido y otro, la sesión registra SQL*Net message from client. Aquí son 2 esperas y 0,001 s: mientras el bloque se ejecuta, la aplicación lo espera, y no al revés (sesión esperando a la aplicación).
• Trace sin esperas. El trace tiene 20.320 esperas (paso 1).
• Disco lento. Toda la clase User I/O suma el 2,4%: aunque bajara a cero, el tiempo total caería como mucho eso.

Queda el tiempo dentro del bloque, entre una sentencia SQL y la siguiente: el código PL/SQL de la rutina trabajando, o el proceso esperando su turno en la CPU en un servidor ocupado. Dividido entre las 180.269 ejecuciones, da unos 0,2 ms entre un SQL y el siguiente. El trace no separa las dos cosas, porque la línea EXEC del bloque, con su CPU, quedó fuera del fragmento. El paso siguiente muestra qué ejecuta la rutina, y cuántas veces.

Véalo en el informe: Perfil del caso 1 y la fila tiempo no contabilizado entre llamadas, cuyo nombre abre la tarjeta con Dónde mirar. 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, los grupos de CPU muestran quién gastó el tiempo que la base de datos midió:

• CPU: PARSE dbcalls: la #2 con el 31,7%, la #1 con el 30,4% y la #3 con el 25,7%;
• CPU: FETCH dbcalls: la #2 con el 50,3% y la #1 con el 49,2%;
• CPU: EXEC dbcalls: la #1 con el 41,3% y la #2 con el 39,5%.

En Sentencias SQL por contribución, la #1 y la #2 son SELECT de profundidad 1, con 89.112 ejecuciones, 89.112 filas y 445.560 lecturas lógicas cada una: una fila y 5 lecturas lógicas por ejecución, sin lectura de disco (PIO 0). Cada ejecución cuesta poco; el costo está en la cantidad. Los tres INSERT con literales en TAB_0001 (#3, #8 y #9) suman 1.217, 350 y 251 ejecuciones, o 1.818, y 89.112 dividido entre 1.818 da 49: la cuenta sugiere que, por cada fila grabada en TAB_0001, la rutina ejecuta la #1 y la #2 49 veces cada una.

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

Paso 5: detalle de la sentencia

Abra la sentencia #1 por el número en la lista o por el enlace Ver sentencia #1 del Diagnóstico. El título lleva la etiqueta 49 variantes: la sentencia es una forma, que agrupa 49 textos que solo difieren en los literales. El texto de la forma es:

SELECT (SELECT COL_0073 FROM TAB_0005 WHERE COL_0074 = :n AND ROWNUM <=:n) AS COL_0073 FROM DUAL

El :n marca el lugar de un número escrito en el texto. El detalle muestra:

• Variantes que más gastaron: las variantes listadas tienen 7.276 o 7.272 llamadas, es decir, 1.819 o 1.818 ejecuciones de cuatro llamadas cada una (PARSE, EXEC, FETCH y CLOSE). Coincide con los 1.818 INSERT en TAB_0001: cada valor se consulta una vez por fila grabada. Los literales aparecen como *** por la máscara (variantes que más gastaron).
• Llamadas: 89.112 PARSE para 89.112 EXEC, con 49 Misses: solo 49 PARSE fueron hard parse. Los demás encontraron el cursor en la library cache, pero costaron una llamada y CPU de todos modos.
• Perfil de la sentencia: CPU de FETCH con el 45,3%, de PARSE con el 31,5% y de EXEC con el 18,3%, sin espera.

Valores en el texto, un texto por valor y un PARSE en cada ejecución: lo más probable es SQL dinámico armado por concatenación dentro de un bucle, con EXECUTE IMMEDIATE o equivalente. Confírmelo en el código de ROT_0001. La #3 sigue el mismo diseño: 1.217 INSERT y 1.217 hard parses, y la CPU de PARSE es el 90,6% de su tiempo. La sección Textos compartibles agrupa esas formas, con los SQL ID ocultos por la máscara (Textos compartibles).

Falta saber qué es TAB_0005. La #10 es TRUNCATE TABLE TAB_0005, y la #16 graba en ella 50 filas: es una tabla de trabajo, que la rutina vacía, llena y después consulta 178.224 veces. El detalle del bloque #4 confirma el paso 1: el cuadro Llamadas solo tiene el PARSE.

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

Paso 6: plan

En el Plan de ejecución de la #1, la nota dice plan registrado 89115 veces, se muestra el registro más lento. El plan sale de las líneas STAT, que el trace trae cuando el cursor se cierra (guía de tracing de 19c): el plan registrado cerca de una vez por ejecución es una señal más de que el cursor se cierra y se abre de nuevo en cada uso.

El cuadro Dónde gasta el plan destaca la operación 2, TABLE ACCESS FULL TAB_0005, con el 86,5% del tiempo y el 100,0% de las lecturas lógicas del plan, y la tarjeta sugiere comprobar si el filtro es selectivo y si hay índice para él. Lea la fila antes de seguir la sugerencia: la operación devuelve 1 fila con 5 lecturas lógicas, en 0,000032 s. Leer entera una tabla de 50 filas cuesta poco. Un índice en COL_0074 ahorraría parte de esas 5 lecturas, pero no las 178.224 ejecuciones ni los PARSE: aquí, el plan no es la causa (operación que concentra el plan).

El plan de la #7, DELETE FROM TAB_0001, muestra un punto menor: INDEX FULL SCAN IDX_0001 leyó 1.870 bloques del índice, y la sentencia no borró ninguna fila. La tabla estaba vacía, pero el índice todavía ocupa esos bloques. La #7 suma 1,023 s, el 2,0% del tiempo total.

Véalo en el informe: operación 2 del plan de la #1. Para leerlo: Plan de ejecución.

Paso 7: esperas y latencia

La Distribución de latencia confirma que el disco queda fuera de la causa. El db file sequential read tiene 1.962 lecturas y suma 1,048 s: el 87,3% de ellas tarda menos de 100 µs, y las 111 que tardan de 1 a 100 ms suman el 92,0% del tiempo del evento. En Lecturas, la tabla Primera lectura y relectura del mismo bloque muestra 1.956 bloques distintos y 6 relecturas: la caché no obliga a leer el mismo bloque de nuevo. De las 1.962 lecturas, 1.870 son del DELETE #7 (paso 6).

En Tipos de llamada, la fila PARSE tiene 180.117 llamadas y 1.920 Misses: casi todos los PARSE son soft parse, y los hard parses vienen casi todos de los textos con literales (muchos hard parses). El peso no está en el hard parse, sino en la cantidad de llamadas: 180.117 PARSE, 180.269 EXEC y 178.460 FETCH en 50 s.

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 IDX_0001, con 0,931 s en 1.877 esperas, casi todas lecturas del DELETE #7. Después vienen el objeto 187750, sin nombre, con 0,165 s en 18.336 esperas de direct path read, y TAB_0005, con 0,023 s. Ningún objeto llega al 2% del tiempo total: el tiempo del caso no está en espera por un objeto, y esta sección solo confirma el punto menor del paso 6.

El nombre sale de las líneas STAT del propio trace, y el objeto sin nombre no aparece en ningún plan. En la consola, el obj# abre la página del objeto, con las consultas para identificarlo en la base de datos (Objetos con más espera).

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

Lo que el fragmento no muestra

El fragmento de 2.000.000 líneas cubre 50,8 s de esta sesión. Lo que queda fuera:

• El final de la rutina. El archivo termina en medio del bloque #4. Los 50,8 s son la parte de la ejecución que cupo en el fragmento, y no la duración de la operación; los recuentos, como las 89.112 ejecuciones, se detienen ahí.
• La CPU del propio PL/SQL. La línea EXEC del bloque traería su CPU y su duración. Sin ella, los 37,419 s entre llamadas no se dividen entre trabajo del PL/SQL y espera por la CPU.
• La contribución de cada sentencia. Sin la llamada de nivel 0, la columna Contribución queda incompleta; compare por el Inclusivo (paso 4).
• Lo que viene después. El commit, otras fases de la rutina y la vuelta a la aplicación quedan fuera del archivo.

Lo mismo vale para un trace suyo desactivado antes del final de la operación, o que se detuvo en el límite de tamaño del archivo (trace cortado). Para medir la operación entera, active el trace antes de que empiece y desactívelo después del final (trace cortado a la mitad).

Causa raíz probable

La rutina ROT_0001, llamada por el bloque #4, procesa fila a fila. Por la cuenta de los pasos 4 y 5, por cada fila que graba en TAB_0001, arma con literales y ejecuta 98 consultas a una tabla de trabajo de 50 filas, 49 de la #1 y 49 de la #2, y un INSERT, también con literales. En el fragmento, son unas 180.000 ejecuciones de SQL, casi todas con su propio PARSE. Una a una cuestan poco, unos 12 s de CPU en total; el tiempo mayor, 37,4 s, queda en el PL/SQL entre una sentencia y otra, o en la espera por la CPU.

Lo que no es la causa: el disco (2,4% del tiempo), la aplicación fuera de la base de datos (0,001 s de espera) y la falta de índice en TAB_0005 (5 lecturas lógicas por ejecución).

Qué hacer

En la aplicación

1. Lea TAB_0005 una vez, antes del bucle, en una colección PL/SQL indexada por la clave, y consulte la colección dentro del bucle. Desaparecen las 178.224 consultas, sus PARSE y el PL/SQL gastado para armar y disparar cada una:

   -- hoy, lo más probable: un SQL armado con el valor en el texto, para cada clave
   execute immediate 'select valor from exemplo_parametros where chave = ' || v_chave
     into v_valor;
   
   -- en memoria: las filas leídas una vez, antes del bucle
   declare
     type t_valores is table of exemplo_parametros.valor%type index by pls_integer;
     v_valores t_valores;
   begin
     for r in (select chave, valor from exemplo_parametros) loop
       v_valores(r.chave) := r.valor;
     end loop;
     -- dentro del bucle, sin ir a la base de datos: v_valor := v_valores(v_chave);
   end;
   /

2. Si es posible, reemplace el bucle entero por un único INSERT ... SELECT que una las tablas de origen con TAB_0005 y grabe todas las filas de TAB_0001 de una vez (fila a fila en PL/SQL).
3. El SQL que siga siendo dinámico debe recibir los valores como bind, con USING, y no en el texto: un cursor sirve para todos los valores, y los hard parses bajan (literales en lugar de bind).

En la base de datos

1. Revise la carga de CPU del servidor en el período del trace, por el historial de sar o del monitoreo. Si había cola de CPU, explica parte de los 37,4 s, y la corrección también pasa por el servidor (tiempo no contabilizado dentro de las llamadas).
2. Mida la rutina con el profiler jerárquico de PL/SQL (DBMS_HPROF), que separa el tiempo de SQL y el de PL/SQL por subprograma (documentación del profiler). Muestra en qué parte del código quedan los 37,4 s.
3. Mientras el código no cambie, CURSOR_SHARING=FORCE en la sesión de la rutina reduce los 1.920 hard parses. Es un paliativo, puede cambiar planes y no quita las ejecuciones ni los PARSE: aquí, la ganancia es pequeña (literales en lugar de bind).
4. Con tiempo, revise el DELETE #7: compruebe el tamaño de IDX_0001 en la página del objeto. Si la tabla se vacía en cada ejecución, evalúe con quien mantiene la rutina reemplazar el DELETE por TRUNCATE, que también vacía los índices de la tabla. TRUNCATE es DDL: confirma la transacción abierta y no se deshace con ROLLBACK (TRUNCATE TABLE).

Cómo confirmar

Active el trace con esperas antes de la llamada a la rutina y desactívelo después del final, antes y después del cambio (activar el trace con DBMS_MONITOR). Con el trace entero, la línea EXEC del bloque entra en el archivo, y el tiempo que hoy aparece entre llamadas pasa al bloque: a CPU: EXEC dbcalls si es trabajo del PL/SQL, o a tiempo no contabilizado dentro de las llamadas si es espera por la CPU. Después del cambio, Llamadas a la base de datos y Tiempo total deben bajar, y los hallazgos de fila a fila y de PARSE en cada ejecución deben desaparecer. Compare los análisis por la columna Tiempo total del Historial (el método).