Posts Tagged ‘DBMS_TRACE’

DBMS_TRACE: PL/SQL sotto controllo.

27 marzo 2010

Fin da oracle8i è disponibile una preziosa utility che consente di mettere sotto trace una sessione di lavoro PL/SQL: DBMS_TRACE.

Il package offre le seguenti funzionalità:

CLEAR_PLSQL_TRACE
Procedura che consente di stoppare una sessione di tracing

GET_PLSQL_TRACE_LEVEL
Funzione che restituisce il livello di tracing corrente

PLSQL_TRACE_VERSION
Procedura che restituisce la versione del package DBMS_TRACE

SET_PLSQL_TRACE
Procedura che avvia una sessione di tracing impostando il livello di tracing.

Per fare un semplice test creiamo una semplice funzione ricorsiva ed una procedura che la chiama:

SQL> create or replace function f1(p number) return number is
  2  a number;
  3  begin
  4    select 1/p into a from dual;
  5    return f1(p-1);
  6  exception
  7    when others then
  8       return 0;
  9  end;
 10  /

Function created.

SQL> create or replace procedure p1 is
  2  a number;
  3  begin
  4    a := f1(3);
  5  end;
  6  /

Procedure created.

La funzione richiama se stessa decrementando il parametro in input finché otterrà un errore (divisione per zero) gestito ritornando zero (e dunque fermando il ciclo).
La procedura innesca la funzione passando il valore 3 come parametro.

Innanzi tutto dobbiamo dire che il package DBMS_TRACE scrive in un paio di tabelle del database che devono essere create lanciando (da SYS) lo script tracetab.sql che si trova nella directory RDBMS/ADMIN sotto la Oracle Home del server.

Una volta lanciato lo script e create le tabelle

SQL> desc sys.plsql_trace_runs
 Nome                    Nullo?   Tipo
 ----------------------- -------- ----------------
 RUNID                   NOT NULL NUMBER
 RUN_DATE                         DATE
 RUN_OWNER                        VARCHAR2(31)
 RUN_COMMENT                      VARCHAR2(2047)
 RUN_COMMENT1                     VARCHAR2(2047)
 RUN_END                          DATE
 RUN_FLAGS                        VARCHAR2(2047)
 RELATED_RUN                      NUMBER
 RUN_SYSTEM_INFO                  VARCHAR2(2047)
 SPARE1                           VARCHAR2(256)

SQL> desc sys.plsql_trace_events
 Nome                    Nullo?   Tipo
 ----------------------- -------- ----------------
 RUNID                   NOT NULL NUMBER
 EVENT_SEQ               NOT NULL NUMBER
 EVENT_TIME                       DATE
 RELATED_EVENT                    NUMBER
 EVENT_KIND                       NUMBER
 EVENT_UNIT_DBLINK                VARCHAR2(4000)
 EVENT_UNIT_OWNER                 VARCHAR2(31)
 EVENT_UNIT                       VARCHAR2(31)
 EVENT_UNIT_KIND                  VARCHAR2(31)
 EVENT_LINE                       NUMBER
 EVENT_PROC_NAME                  VARCHAR2(31)
 STACK_DEPTH                      NUMBER
 PROC_NAME                        VARCHAR2(31)
 PROC_DBLINK                      VARCHAR2(4000)
 PROC_OWNER                       VARCHAR2(31)
 PROC_UNIT                        VARCHAR2(31)
 PROC_UNIT_KIND                   VARCHAR2(31)
 PROC_LINE                        NUMBER
 PROC_PARAMS                      VARCHAR2(2047)
 ICD_INDEX                        NUMBER
 USER_EXCP                        NUMBER
 EXCP                             NUMBER
 EVENT_COMMENT                    VARCHAR2(2047)
 MODULE                           VARCHAR2(4000)
 ACTION                           VARCHAR2(4000)
 CLIENT_INFO                      VARCHAR2(4000)
 CLIENT_ID                        VARCHAR2(4000)
 ECID_ID                          VARCHAR2(4000)
 ECID_SEQ                         NUMBER
 CALLSTACK                        CLOB
 ERRORSTACK                       CLOB

Possiamo attivare la trace:

SQL> begin
  2  DBMS_TRACE.SET_PLSQL_TRACE (
  3      DBMS_TRACE.TRACE_ALL_CALLS+
  4      DBMS_TRACE.TRACE_ALL_EXCEPTIONS+
  5      DBMS_TRACE.TRACE_ALL_SQL);
  6  end;
  7  /

PL/SQL procedure successfully completed.

Nell’attivazione della trace dobbiamo impostare il livello di tracing, cioè definire quali eventi monitorare.
Ciò si fa sommando le costanti relative agli eventi che interessano, le costanti di maggiore interesse sono:

TRACE_ALL_CALLS             1
TRACE_ENABLED_CALLS         2
TRACE_ALL_EXCEPTIONS        4
TRACE_ENABLED_EXCEPTIONS    8
TRACE_LIMIT                 16
TRACE_ALL_SQL               32
TRACE_ENABLED_SQL           64
TRACE_ALL_LINES             128
TRACE_ENABLED_LINES         256
NO_TRACE_ADMINISTRATIVE     32768
NO_TRACE_HANDLED_EXCEPTIONS 65536

Ad ogni costante è associato come valore numerico una potenza di due e dunque è possibile scomporre ogni possibile livello di tracing nelle singole costanti che lo compogono.
Per ottenere il livello di tracing si può fare:

SQL> select dbms_trace.GET_PLSQL_TRACE_LEVEL from dual;

GET_PLSQL_TRACE_LEVEL
---------------------
                   37

Per ottenere invece la versione del package:

SQL> var v1 number;
SQL> var v2 number;
SQL> exec dbms_trace.PLSQL_TRACE_VERSION(:v1,:v2)

Procedura PL/SQL completata correttamente.

SQL> print v1

        V1
----------
         1

SQL> print v2

        V2
----------
         0

Tornando al nostro esempio, siamo pronti per eseguire p1 con la trace attiva:

SQL> exec p1

Procedura PL/SQL completata correttamente.

SQL> select runid, count(0) from sys.plsql_trace_events
  2  group by runid;

     RUNID   COUNT(0)
---------- ----------
         1          7
         2          7
         3         52
         4          7
         5         24

Come si vede ci sono vari runid in tabella dovuti a diverse prove che ho fatto. L’ultimo è quello che ci interessa.
La tabella plsql_trace_events contiene molte informazioni utili, per ragioni di formattazione della pagina io sono costretto a mostrarne solo poche:

SQL> select EVENT_SEQ, event_kind, event_unit, event_comment
  2  from sys.plsql_trace_events
  3  where runid=5;

 EVENT_SEQ EVENT_KIND EVENT_UNIT
---------- ---------- -------------------------------
EVENT_COMMENT
----------------------------------------------------------------------
         1         38
PL/SQL Trace Tool started

         2         40
Trace flags changed

         3         50 DBMS_TRACE
Return from procedure call

         4         50 DBMS_TRACE
Return from procedure call

         5         50 DBMS_TRACE
Return from procedure call

         6         44
PL/SQL Virtual Machine stopped

         7         43 <anonymous>
PL/SQL Virtual Machine started

         8         45 <anonymous>
Procedure Call

         9         45 P1
Procedure Call

        10         54 F1
SELECT 1/:B1 FROM DUAL

        11         45 F1
Procedure Call

        12         54 F1
SELECT 1/:B1 FROM DUAL

        13         45 F1
Procedure Call

        14         54 F1
SELECT 1/:B1 FROM DUAL

        15         45 F1
Procedure Call

        16         54 F1
SELECT 1/:B1 FROM DUAL

        17         52 F1
Exception raised

        18         53 F1
Exception handled

        19         50 F1
Return from procedure call

        20         50 F1
Return from procedure call

        21         50 F1
Return from procedure call

        22         50 F1
Return from procedure call

        23         50 P1
Return from procedure call

        24         44
PL/SQL Virtual Machine stopped


Selezionate 24 righe.

Come si vede ci sono alcuni eventi di sistema (la cui tracciatura può essere soppressa utilizzando la costante NO_TRACE_ADMINISTRATIVE) e molti eventi applicativi che avevo richiesto (le query eseguite, le eccezioni sollevate e gestite, le chiamate tra programmi).

Un altro utile campo è il CALLSTACK, valorizzato solo su alcuni eventi particolari:

SQL> select event_seq, CALLSTACK
  2  from sys.plsql_trace_events
  3  where runid=5;

 EVENT_SEQ CALLSTACK
---------- ----------------------------------------------------------
         1
         2 ----- PL/SQL Call Stack -----
             object      line  object
             handle    number  name
           1CDCDB88        21  package body SYS.DBMS_TRACE
           1CDCDB88        75  package body SYS.DBMS_TRACE
           1CDCDB88        80  package body SYS.DBMS_TRACE
           1CDCFD7C         2  anonymous block

         3
         4
         5
         6
         7
         8
         9
        10
        11
        12
        13
        14
        15
        16
        17 ----- PL/SQL Call Stack -----
             object      line  object
             handle    number  name
           1CF6A894         4  function MAXR.F1
           1CF6A894         5  function MAXR.F1
           1CF6A894         5  function MAXR.F1
           1CF6A894         5  function MAXR.F1
           1CDB5A58         4  procedure MAXR.P1
           1CDC5888         1  anonymous block

        18 ----- PL/SQL Call Stack -----
             object      line  object
             handle    number  name
           1CF6A894         8  function MAXR.F1
           1CF6A894         5  function MAXR.F1
           1CF6A894         5  function MAXR.F1
           1CF6A894         5  function MAXR.F1
           1CDB5A58         4  procedure MAXR.P1
           1CDC5888         1  anonymous block

        19
        20
        21
        22
        23
        24

Selezionate 24 righe.

Che visualizza proprio la pila di chiamate tra programmi.

Una volta raccolte le informazioni necessarie ricordiamoci di disattivare la trace usando:

SQL> exec DBMS_TRACE.CLEAR_PLSQL_TRACE

Procedura PL/SQL completata correttamente.

Altrimenti la tabella degli eventi si riempe molto velocemente…

Alla prossima,
Massimo