Como determinar tiempo transcurrido en milisegundos

Se puede usar SYSDATE para realizar cálculos de rendimiento. Un programador que sólo tenga acceso a SQL*Plus usaría SYSDATE antes y después de llamar a una función para medir su rendimiento. Sin embargo, hay un problema... la máxima precisión de SYSDATE es en "segundos".

Existen situaciones donde se requiere mayor precisión, en escala de milisegundos. Un ejemplo es medir el rendimiento de una función que, aunque la medición tradicional retorne que duró 0 segundos (usando SYSDATE), resulta que realizando aproximadamente 400000 llamadas en ambiente productivo la aplicación tarda 10 minutos en responder. Se requiere determinar el rendimiento en milisegundos de la función para ver donde está ocurriendo el lapso que retrasa el rendimiento.

A partir de Oracle 9i se introduce el comando SYSTIMESTAMP, cuya precisión máxima es en milisegundos.

SELECT SYSTIMESTAMP FROM DUAL ; 

Resultado:

SQL> SELECT SYSTIMESTAMP FROM DUAL ;

SYSTIMESTAMP
---------------------------------------------------------------------------
12-APR-12 05.16.38.678190 AM -04:30

SQL>

Ejemplo de análisis de rendimiento con SYSDATE (para analizar rendimientos que superan 1 segundo):

SQL> CREATE PROCEDURE pesimo IS 
 v_ineficiente NUMBER ; 
BEGIN

 -- Tabla con 14809 registros y ponemos a 
 -- trabajar el servidor para que
 -- cuente 219306481 registros
 SELECT COUNT(*) 
   INTO v_ineficiente 
   FROM tabla, tabla
 ;
 
END ; 
/

Procedure created.

SQL> SET SERVEROUTPUT ON ;
SQL> DECLARE
  2     v_d1 DATE ;
  3     v_d2 DATE ;
  4     v_n  NUMBER ;
  5  BEGIN
  6     v_d1 := SYSDATE ;
  7     pesimo ;
  8     v_d2 := SYSDATE ;
  9     v_n := ( v_d2-v_d1 ) * 86400 ;
 10     DBMS_OUTPUT.PUT_LINE( 'Tiempo transcurrido : '
 11          ||v_n|| ' segundos'  ) ;
 12  END ;
 13  /
Tiempo transcurrido : 92 segundos

PL/SQL procedure successfully completed.

Elapsed: 00:01:31.09
SQL>

Ejemplo de análisis de rendimiento con SYSTIMESTAMP (cuando se requiere milisegundos de precisión):

CREATE PROCEDURE rapido IS 
 v_eficiente NUMBER ; 
BEGIN

        -- Tabla con 51500 registros
 SELECT COUNT(*) 
   INTO v_eficiente 
   FROM tabla_rapida
  WHERE fecha = 20120110
 ;
 
END ; 
/

Procedure created.

SQL> SET SERVEROUTPUT ON ;
SQL> DECLARE
  2     v_d1 TIMESTAMP ;
  3     v_d2 TIMESTAMP ;
  4     v_n  INTERVAL DAY TO SECOND ;
  5  BEGIN
  6     v_d1 := SYSTIMESTAMP ;
  7     rapido ;
  8     v_d2 := SYSTIMESTAMP ;
  9     v_n := v_d2-v_d1 ;
 10     DBMS_OUTPUT.PUT_LINE( 'Tiempo transcurrido : '
 11       ||EXTRACT( SECOND FROM v_n )|| ' segundos'  ) ;
 12  END ;
 13  /
Tiempo transcurrido : .064362 segundos

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.01
SQL>

En un escenario donde no se dispone de recursos DBA (por cualquier motivo) y el usuario oracle asignado no permite ver los planes de ejecución ni el costo de consumo de recursos y se requiere una solución inmediata, entonces el programador puede deducir que cualquier query/función/procedimiento que tarde por ejemplo 0.02 segundos en retornar, por muy rápida que parezca, no se puede ejecutar 400000 veces y pretender que dure menos de 30 segundos en el total de todas sus ejecuciones (tardaba 10 minutos en el momento que se me asignó el módulo). Para lograr el objetivo se debían entonar los 15 queries que se ejecutan dentro de la función por cada llamada(algunos con más de 9 tablas cruzadas y subqueries en sus cláusulas FROM y WHERE). La solución fue analizarlas con varios SYSTIMESTAMP en cada instrucción porque SYSDATE siempre devolvería 0 segundos.

Gracias a esta técnica se pudo determinar cuales eran las tablas que no estaban operando adecuadamente y se entonaron hasta que se logró un tiempo menor a 0.001 segundos por query, al punto que al momento de realizar las 400000 llamadas retornaba en 32 segundos.