16 April, 2012

Timer in PLSQL and SQL

Sometime when developing code in PLSQL, we need to trace time of execution in run-time.
So I will create timer package to help us.
I will divide this post to two partition
1- Timer in PLSQL
    This will trace time of PLSQL code
2- Timer in SQL
    This will trace time of SQL code



1- Timer in PLSQl
Tracing time of PLSQL code doesn't exist directly in Oracle Database, So I will develop package for doing this task 

Package Analysis
I will list requirements needed in timer package
1-create multiple instances of timers
2-strat timer and stop timer and drop timer
3-Show period in different format
4-Enable and disable timer function due to package variable
5-show elapsed time
6-show whole properties of timer
7-List all used timers

Package Developing
I created package regarding my requirement.
You can discover code and use it to check performance of your code and know which bulk of your code takes more time than expected.


Package Specification

 CREATE OR REPLACE PACKAGE MAH_TIMER  
 IS  
   GB$ENABLED  BOOLEAN := TRUE;  
   --store timer properties in below record type  
   TYPE GR$TIMER IS RECORD (  
    TIMER_NAME   VARCHAR2 (100),  
    START_TIME   NUMBER,  
    STOP_TIME   NUMBER,  
    ELAPSED_TIME  NUMBER  
   );  
   --store list of timers in below table  
   TYPE GT$TIMER IS TABLE OF GR$TIMER  
             INDEX BY PLS_INTEGER;  
   GV$TIMER   GT$TIMER;  
   --use it to enable timer function  
   PROCEDURE ENABLE_TIMER;  
   --use it to enable disable function  
   PROCEDURE DISABLE_TIMER;  
   --check if timer function is enabled  
   FUNCTION IS_TIMER_ENABLED  
    RETURN BOOLEAN;  
   --Get index of timer in GV$TIMER collection  
   FUNCTION FIND_TIMER (IN_TIMER_NAME VARCHAR2 DEFAULT 'DEFAULT_TIMER')  
    RETURN PLS_INTEGER;  
   --use it to start new timer  
   PROCEDURE START_TIMER (IN_TIMER_NAME VARCHAR2 DEFAULT 'DEFAULT_TIMER');  
   --use it to stop already exist timer  
   PROCEDURE STOP_TIMER (IN_TIMER_NAME VARCHAR2 DEFAULT 'DEFAULT_TIMER');  
   -- use it to print properties of timer  
   PROCEDURE SHOW_TIMER (IN_TIMER_NAME VARCHAR2 DEFAULT 'DEFAULT_TIMER');  
   --use it to print elapse time of timer  
   PROCEDURE SHOW_ELAPSED (IN_TIMER_NAME VARCHAR2 DEFAULT 'DEFAULT_TIMER');  
   --use it to get list of current timers in GV$TIMER collection  
   FUNCTION list_timer  
    RETURN SYS.ODCIVARCHAR2LIST;  
   --use it to drop time  
   PROCEDURE drop_timer (IN_TIMER_NAME VARCHAR2 DEFAULT 'DEFAULT_TIMER');  
 END;  

Package Body

 CREATE OR REPLACE PACKAGE BODY MAH_TIMER  
 IS  
   PROCEDURE ENABLE_TIMER  
   IS  
   BEGIN  
    GB$ENABLED := TRUE;  
   END ENABLE_TIMER;  
   PROCEDURE DISABLE_TIMER  
   IS  
   BEGIN  
    GB$ENABLED := FALSE;  
   END DISABLE_TIMER;  
   FUNCTION IS_TIMER_ENABLED  
    RETURN BOOLEAN  
   IS  
   BEGIN  
    RETURN GB$ENABLED;  
   END IS_TIMER_ENABLED;  
   FUNCTION FIND_TIMER (IN_TIMER_NAME VARCHAR2 DEFAULT 'DEFAULT_TIMER')  
    RETURN PLS_INTEGER  
   IS  
   BEGIN  
    FOR INDX IN 1 .. GV$TIMER.COUNT  
    LOOP  
      IF GV$TIMER (INDX).TIMER_NAME = IN_TIMER_NAME  
      THEN  
       RETURN INDX;  
      END IF;  
    END LOOP;  
    --IF NOT EXISTS THEN RETURN NULL  
    RETURN NULL;  
   END FIND_TIMER;  
   PROCEDURE START_TIMER (IN_TIMER_NAME VARCHAR2 DEFAULT 'DEFAULT_TIMER')  
   IS  
    LN$INDX  PLS_INTEGER;  
   BEGIN  
    LN$INDX := FIND_TIMER (IN_TIMER_NAME);  
    IF LN$INDX IS NULL AND IS_TIMER_ENABLED  
    THEN  
      LN$INDX := GV$TIMER.COUNT + 1;  
      GV$TIMER (LN$INDX).TIMER_NAME := IN_TIMER_NAME;  
      GV$TIMER (LN$INDX).START_TIME := DBMS_UTILITY.GET_TIME;  
    ELSIF LN$INDX IS NOT NULL  
    THEN  
      DBMS_OUTPUT.PUT_LINE (IN_TIMER_NAME || 'is already started !!!');  
    END IF;  
   END START_TIMER;  
   PROCEDURE STOP_TIMER (IN_TIMER_NAME VARCHAR2 DEFAULT 'DEFAULT_TIMER')  
   IS  
    LN$INDX  PLS_INTEGER;  
   BEGIN  
    LN$INDX := FIND_TIMER (IN_TIMER_NAME);  
    IF LN$INDX IS NOT NULL  
    THEN  
      GV$TIMER (LN$INDX).STOP_TIME := DBMS_UTILITY.GET_TIME;  
      GV$TIMER (LN$INDX).ELAPSED_TIME :=  
       GV$TIMER (LN$INDX).STOP_TIME - GV$TIMER (LN$INDX).START_TIME;  
    ELSIF LN$INDX IS NULL  
    THEN  
      DBMS_OUTPUT.  
      PUT_LINE (IN_TIMER_NAME || ' doesn''t exists to stop it !!!');  
    END IF;  
   END STOP_TIMER;  
   PROCEDURE SHOW_TIMER (IN_TIMER_NAME VARCHAR2 DEFAULT 'DEFAULT_TIMER')  
   IS  
    LN$INDX  PLS_INTEGER;  
   BEGIN  
    LN$INDX := FIND_TIMER (IN_TIMER_NAME);  
    IF LN$INDX IS NOT NULL  
    THEN  
      DBMS_OUTPUT.  
      PUT_LINE (  
         IN_TIMER_NAME  
       || ' started on '  
       || GV$TIMER (LN$INDX).START_TIME  
       || '  , Stopped on '  
       || GV$TIMER (LN$INDX).STOP_TIME  
       || '  , Elapsed Time '  
       || GV$TIMER (LN$INDX).ELAPSED_TIME);  
    ELSIF LN$INDX IS NULL  
    THEN  
      DBMS_OUTPUT.  
      PUT_LINE (  
       IN_TIMER_NAME || ' doesn''t exists to show its properties !!!');  
    END IF;  
   END SHOW_TIMER;  
   PROCEDURE SHOW_ELAPSED (IN_TIMER_NAME VARCHAR2 DEFAULT 'DEFAULT_TIMER')  
   IS  
    LN$INDX  PLS_INTEGER;  
   BEGIN  
    LN$INDX := FIND_TIMER (IN_TIMER_NAME);  
    IF LN$INDX IS NOT NULL  
    THEN  
      DBMS_OUTPUT.  
      PUT_LINE (  
         ' Elapsed Time of timer '  
       || IN_TIMER_NAME  
       || ' is '  
       || GV$TIMER (LN$INDX).ELAPSED_TIME);  
    ELSIF LN$INDX IS NULL  
    THEN  
      DBMS_OUTPUT.  
      PUT_LINE (  
       IN_TIMER_NAME || ' doesn''t exists to show its elapsed time !!!');  
    END IF;  
   END SHOW_ELAPSED;  
   FUNCTION LIST_TIMER  
    RETURN SYS.ODCIVARCHAR2LIST  
   IS  
    LT$TIMER_NAMES  SYS.ODCIVARCHAR2LIST := SYS.ODCIVARCHAR2LIST ();  
   BEGIN  
    FOR INDX IN 1 .. Gv$TIMER.COUNT  
    LOOP  
      LT$TIMER_NAMES.EXTEND;  
      LT$TIMER_NAMES (INDX) := Gv$TIMER (INDX).TIMER_NAME;  
    END LOOP;  
    RETURN LT$TIMER_NAMES;  
   END LIST_TIMER;  
   PROCEDURE drop_timer (IN_TIMER_NAME VARCHAR2 DEFAULT 'DEFAULT_TIMER')  
   IS  
    LN$INDX  PLS_INTEGER;  
   BEGIN  
    LN$INDX := FIND_TIMER (IN_TIMER_NAME);  
    IF LN$INDX IS NOT NULL  
    THEN  
      GV$TIMER (LN$INDX) := NULL;  
    ELSIF LN$INDX IS NULL  
    THEN  
      DBMS_OUTPUT.  
      PUT_LINE (IN_TIMER_NAME || ' doesn''t exists to drop it !!!');  
    END IF;  
   END drop_timer;  
 END MAH_TIMER;  

Let's now run below script and test my package

 DECLARE  
   LT$TIMERS  SYS.ODCIVARCHAR2LIST := SYS.ODCIVARCHAR2LIST ();  
 BEGIN  
   MAH_TIMER.START_TIMER;  
   MAH_TIMER.START_TIMER ('timer1');  
   FOR I IN 1 .. 100000000  
   LOOP  
    IF I = 50000  
    THEN  
      MAH_TIMER.STOP_TIMER ('timer1');  
    END IF;  
    IF I = 70000  
    THEN  
      MAH_TIMER.START_TIMER ('timer2');  
    END IF;  
   END LOOP;  
   MAH_TIMER.START_TIMER ('timer3');  
   MAH_TIMER.SHOW_TIMER ('timer1');  
   MAH_TIMER.SHOW_TIMER ('timer2');  
   MAH_TIMER.SHOW_ELAPSED ('timer1');  
   MAH_TIMER.STOP_TIMER ('timer2');  
   MAH_TIMER.SHOW_TIMER ('timer2');  
   MAH_TIMER.SHOW_TIMER ('timer3');  
   MAH_TIMER.STOP_TIMER ('timer3');  
   MAH_TIMER.drop_TIMER ('timer3');  
   --list timers  
   DBMS_OUTPUT.put_line ('List Timers ::::');  
   LT$TIMERS := MAH_TIMER.LIST_TIMER;  
   FOR INDX IN LT$TIMERS.FIRST .. LT$TIMERS.LAST  
   LOOP  
    DBMS_OUTPUT.PUT_LINE (LT$TIMERS (INDX));  
   END LOOP;  
   MAH_TIMER.show_TIMER ('timer3');  
   MAH_TIMER.STOP_TIMER;  
   MAH_TIMER.SHOW_TIMER;  
 END;  

The output like below

 DEFAULT_TIMERis already started !!!  
 timer1is already started !!!  
 timer2is already started !!!  
 timer1 started on 2011313411  , Stopped on 2011357412  , Elapsed Time 44001  
 timer2 started on 2011313412  , Stopped on 2011333950  , Elapsed Time 20538  
  Elapsed Time of timer timer1 is 44001  
 timer2 started on 2011313412  , Stopped on 2011357953  , Elapsed Time 44541  
 timer3 started on 2011357953  , Stopped on  , Elapsed Time   
 List Timers ::::  
 DEFAULT_TIMER  
 timer1  
 timer2  
 timer3 doesn't exists to show its properties !!!  
 DEFAULT_TIMER started on 2011313411  , Stopped on 2011357953  , Elapsed Time 44542  

2- Timer in SQL
Let's now play with Oracle Data Dictionary Views to get what we need of tracing time of execution SQL statements.

I will use V$SQL view to get time of execution per every SQL statement run against DB.

  SELECT sql_id,  
      sql_text,  
      elapsed_time,  
      plsql_exec_time  
   FROM v$sql  
   WHERE plsql_exec_time > 0 AND elapsed_time > 0  
 ORDER BY plsql_exec_time DESC  

You can also get time per every category execution in database from v$sys_time_model View

 SELECT * FROM v$sys_time_model;  

The result is below






















 
Conclusion
Always use timer to track efficiency of your code.
Efficiency of code save time and cost in future.

Thanks
Mahmoud A. El-Sayed

1 comment:

  1. Dear BOSS ...

    This is simply superb .. you are a true genius dude ...

    ReplyDelete

ADF : Scope Variables

Oracle ADF uses many variables and each variable has a scope. There are five scopes in ADF (Application, Request, Session, View and PageFl...