tic... toc

¿Cómo medir la performance de un código PL/SQL?

Muchas veces nos encontramos con procedimientos lentos de muchos pasos, con llamadas a funciones, DML, loops con cursores, etc, que queremos revisar. Como SYSDATE nos da la cantidad de segundos como mínima fracción de tiempo, no nos es de mucha ayuda consultarlo entre líneas.

Afortunadamente, contamos con la función get_time del paquete dbms_utility para obtener la cantidad de centésimas de segundo que transcurren entre dos instantes de tiempo.
A sabiendas de eso, debemos incluir los statements que invoquen a dichas funciones y desplieguen los tiempos por la salida, en un archivo o en una tabla de logs.

Con el fin de evitar duplicar código y además aprovechar las bondades del cacheado de paquetes en el área de memoria compartida, creé un pequeño paquete exclusivo para ese fin. El mismo tiene dos procedimientos: tic y toc. Cuando quiero comenzar a medir tiempo, invoco a tic (con un mensaje para registro). Cuando quiero medir el tiempo transcurrido, uso toc. Así de simple.

CREATE OR REPLACE PACKAGE crono AS
  v_tic PLS_INTEGER;
  evento VARCHAR2(100);
  PROCEDURE tic(p_evento IN VARCHAR2);
  PROCEDURE toc;
END crono;
/

CREATE OR REPLACE PACKAGE BODY crono AS
 PROCEDURE tic(p_evento IN VARCHAR2) IS
 BEGIN
   v_tic := DBMS_UTILITY.GET_TIME;
   evento := p_evento;
   DBMS_OUTPUT.PUT_LINE('TIC: '||p_evento);
 END tic;

 PROCEDURE toc IS
   df pls_integer := CAST(DBMS_UTILITY.GET_TIME AS PLS_INTEGER)-v_tic;
 BEGIN
   DBMS_OUTPUT.PUT_LINE('TOC: '||evento||', T(1/100s): '||df);
 END toc;
END crono;
/

El uso del paquete en un procedimiento cualquiera puede ser:

SQL> begin
2     crono.tic('creo tabla');
3     execute immediate 'CREATE TABLE testtable as select * from user_tables';
4     crono.toc;
5     crono.tic('elimino registros');
6     execute immediate 'delete from testtable';
7     crono.toc;
8     crono.tic('hago commit');
9     commit;
10     crono.toc;
11     crono.tic('borro tabla');
12     execute immediate 'drop table testtable';
13     crono.toc;
14 end;
15 /
TIC: creo tabla
TOC: creo tabla, T(1/100s): 34
TIC: elimino registros
TOC: elimino registros, T(1/100s): 5
TIC: hago commit
TOC: hago commit, T(1/100s): 0
TIC: borro tabla
TOC: borro tabla, T(1/100s): 50

Procedimiento PL/SQL terminado correctamente.

Aunque esta experiencia es meramente demostrativa, notar que no pasó un segundo en toda la operación, y sin embargo estamos sacando medidas ilustrativas en cada paso.

Es una solución práctica y disponible para todos los usuarios de la base de datos, solo tengo que dar permisos de ejecución a los desarrolladores o a public. Un sinónimo puede simplificar aún más las llamadas a tic y a toc.

Pese al mínimo costo de salida por pantalla, una desventaja es que el procedimiento tiene que terminar exitosamente para obtener las medidas (dbms_output despliega su salida al final del proceso). Una alternativa para lograr la medición "on the run", es implementar la salida a archivo (utilizando el paquete utl_file), o insertando en una tabla (con una transacción autónoma para no hacer commit sobre la actual).
Estos cambios pueden ser transparentes al usuario, ya que solo hará falta recompilar el body del paquete. Las ventajas están a la vista.

Ver también:
Uso del paquete utl_file