Éléments avancés sur les traces Oracle (bind variables, wait events). Evènement 10046

Logo

Introduction

Les analyses des traces tkprof Oracle peuvent être parfois désarmantes lorsque ces dernières reportent des informations relatives à des requêtes comprenant des variables attachées (bind variables), en effet les valeurs de variables attachées ne sont pas données par défaut :

Exemple :


select TRACE01.TYPE ,TRACE01.STATUS ,TRACE01.SEQUENCE
from
 TRACE TRACE01 where TRACE01.TYPE=NVL(RTRIM(:b1,' '),' ')

call     count       cpu   elapsed    disk      query    current      rows
------- ------  -------- --------- -------- ---------- ----------  --------
Parse        4      0.01      0.00        0          0          0         0
Execute  19012      3.10      3.56        0          0          0         0
Fetch    19012   1056.38   1517.15        0   43282981      76048     19012
------- ------  -------- --------- -------- ---------- ----------  --------
total    38028   1059.49   1520.71        0   43282981      76048     19012

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 33  (OPS$MAXBATCH)

Rows     Row Source Operation
-------  ---------------------------------------------------
   4905  TABLE ACCESS FULL TRACE

Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   GOAL: CHOOSE
   4905   TABLE ACCESS   GOAL: ANALYZED (FULL) OF 'TRACE'

Cet article va s’attarder sur les méthodes permettant de récupérer les valeurs des variables attachées dans les requêtes au cours de trace Oracle. L’article s’étend également sur la récupération d’autres valeurs intéressantes comme les évènements d’attente dans les traces tkprof.

Parmi ces méthodes :

  • évènement 10046
  • oradebug
  • dbms_support
  • Trace analyzer
  • dbms_monitor (Oracle 10g uniquement)

Rappels

Rappels sur les paramètres d’initialisation liés aux fichiers de trace

Avant de pouvoir lancer une trace Oracle, il faut pouvoir la générer. Une trace peut être mise en place pour une instance ou une session.

Lorsqu’une session est tracée, Oracle génère un fichier qui contient toutes les statistiques concernant les instructions SQL exécutées pendant cette session.

Les paramètres d’initialisation de l’instance à activer ou valider pour avoir une trace sont : timed_statistics, user_dump_dest, et max_dump_file_size.

Paramètre timed_statistics

Positionné à true, ce paramètre va permettre à Oracle de fournir des informations temporelles. Les statistiques temporelles sont exprimées en microsecondes.

Pour retrouver la valeur de ce paramètre d’initialisation :

show parameter timed_statistics;

----
true
select name, value from v$parameter where name='timed_statistics';

----
true

Paramètre user_dump_dest

Pour rappel, les fichiers de trace sur une session sont écrits par Oracle dans le répertoire donné par la variable user_dump_dest qui est un paramètre d’initialisation de l’instance Oracle. Pour retrouver la valeur de ce paramètre d’initialisation :

show parameter user_dump_dest;

-----------------------------------------
/Software/oracle/Instances/CLWU1ORA/udump

select name, value from v$parameter where name='user_dump_dest';

-----------------------------------------
/Software/oracle/Instances/CLWU1ORA/udump

Le paramètre user_dump_dest est modifiable par la commande alter system :

alter system set user_dump_dest = ...;

System alered.

Paramètre max_dump_file_size

La taille maximale d’un fichier de trace est gouvernée par le paramètre d’initialisation max_dump_file_size. Il est exprimé en octets et si la taille du fichier de trace dépasse ce paramètre, la trace est tronquée avec génération d’un message. Afin de ne pas être limité, la valeur UNLIMITED est acceptée.

Pour retrouver la valeur de ce paramètre d’initialisation :

show parameter max_dump_file_size;

select name, value from v$parameter where name='max_dump_file_size'

Le paramètre max_dump_file_size est modifiable par la commande alter session :

alter system set max_dump_file_size = unlimited;

Session altered.

Rappels sur l’exécution de traces de sessions et utilisation de tkprof

Exécutions de traces (alter session et dbms_system.set_sql_trace_in_session)

Pour tracer la session courante :

alter session set sql_trace=true;

Pour tracer une session différente :

exec sys.dbms_system.set_sql_trace_in_session (sid,serial#,true);

Le fichier de trace est alors généré dans le répertoire indiqué par le paramètre user_dump_dest et le nom de ce fichier a généralement la nomenclature <$ORACLE_SID>_ora_<ProcessID>.trc

ProcessID est l’identifiant du processus serveur. Celui-ci peut être retrouvé dans la colonne SPID de la vue système V$PROCESS :

select s.username nom_utilisateur ,
       p.spid processs_serveur ,
       s.program
from v$session s , v$process p
where s.sid = <sid>
      and s.serial# = <serial#>
      and s.addr=p.addr ;

Ce mode d’analyse n’est valable qu’en mode dédié (dedicated) pour l’instance.

Interprétation des fichiers de trace avec le binaire tkprof

Tkprof est un binaire et ne peut être appelé depuis SQL*Plus.

La syntaxe est la suivante :

Unix > tkprof <fichier_de_trace> <fichier_de_sortie> [options]

Exemple :

Unix > tkprof CLWU1ORA_ora_17898.trc CLWU1ORA_ora_17898.txt sys=no aggregate=no EXPLAIN=SIEBEL/SIEBEL

Dans la syntaxe ci-dessus très couramment utilisée : le fichier de trace CLWU1ORA_ora_17898.trc est analysé et le résultat est écrit dans le fichier CLWU1ORA_ora_17898.txt.

  • sys=no indique que l’on ne souhaite pas voir les requêtes internes à Oracle.
  • aggregate=no indique que l’on ne souhaite pas que les requêtes identiques soient agrégées dans le résultat
  • explain=SIEBEL/SIEBEL indique que l’on souhaite voir apparaître les plans d’exécution associés en indiquant le user et le mot de passe du user associé.

Evènement de trace 10046 (Oracle 8i et 9i) et ORADEBUG

Niveaux de l’évènement de trace 10046 (level 4, 8 ou 12)

L’évènement de trace 10046 en fonction du niveau (4, 8, ou 12) permet d’attraper dans les fichiers de trace les valeurs des variables attachées dans les requêtes et/ou les évènements d’attente des requêtes. Voici la description des niveaux :

Trace commentaire
10046 trace name context forever, level 4 Trace les requêtes SQL et montre les valeurs des variables attachées dans lefichier de trace
10046 trace name context forever, level 8 Affiche les évènements d’attente dans le fichier de trace des requêtesSQL
10046 trace name context forever, level 12 Affiche à la fois les évènements d’attente et les valeurs des variables attachées des requêtes SQL dans le fichier de trace

Appliquer l’évènement de trace 10046 à sa propre session

Lorsqu’il s’agit d’appliquer l’évènement de trace 10046 sur sa propre session, la commande alter session suffit largement :

alter session set events '10046 trace name context forever, level 12';

alter session set sql_trace=true;
...

Pour désactiver l’évènement de trace 10046 sur sa propre session :

alter session set events '10046 trace name context off';

Appliquer l’évènement de trace 10046 sur une session différente (ORADEBUG)

ORADEBUG disponible avec SQL*Plus peut être utilisé pour appliquer l’évènement de trace 10046 sur une session différente, pour cela on aura besoin du SPID de la session à tracer (voir paragraphe précédent sur l’exécution de traces)

oradebug setospid 17898;
Oracle pid: 91, Unix process pid: 17898, image: oracleorcl
oradebug event 10046 trace name context forever, level 12;
Statement processed.

Pour afficher le fichier de trace généré avec oradebug :

oradebug tracefile_name;
          
/Software/oracle/Instances/CLWU1ORA/udump/CLWU1ORA_ora_17898.trc

Pour désactiver l’évènement de trace 10046 sur la session avec oradebug :

oradebug event 10046 trace name context forever, level 12;

Statement processed.

DBMS_SUPPORT (Oracle 8i et 9i)

Le package DBMS_SUPPORT simplifie les choses avec Oracle 8i et 9i, mais ce dernier n’est pas installé par défaut et doit être chargé en tant que sys, pour l’installer :

@?\rdbms\admin\dbmssupp.sql

Package created.
Package body created.

Avec ce package, il est possible de spécifier les paramètres waits => true|fale et binds => true|false afin de générer les évènements d’attente et les valeurs des variables attachées dans les fichiers de trace.

Lorsqu’il s’agit de sa propre session :

exec dbms_support.start_trace ( waits=>true, binds=>true);
...  ...
exec dbms_support.stop_trace;

Lorsqu’il s’agit d’une session différente :

exec dbms_support.start_trace_in_session ( 10,20,waits=>true, binds=>true);
...  ...
exec dbms_support.stop_trace_in_session(10,20);

DBMS_MONITOR (Oracle 10g)

Avec Oracle 10g, tout a été centralisé et étendu avec le package DBMS_MONITOR pour lequel les paramètres waits et binds sont disponibles de la même manière que le package DBMS_SUPPORT.

Lorsqu’il s’agit de sa propre session :

exec dbms_monitor.session_trace_enable ( waits=>true, binds=>true);
...  ...
exec dbms_monitor.session_trace_disable;

Lorsqu’il s’agit d’une session différente :

exec dbms_monitor.session_trace_enable (session_id=>10,serial_num=> 20, waits=>true, binds=>true);
...  ...
exec dbms_monitor.session_trace_disable ( session_id=>10,serial_num=> 20 );

Lorsqu’il s’agit d’un client clairement connu grâce à la colonne client_identifier de la vue V$SESSION (valeur appliquée par le client avec le package DBMS_SESSION) :

exec dbms_monitor.session_trace_enable (client_id=>'bureau_128',waits=>true, binds=>true);
...  ...
exec dbms_monitor.session_trace_disable ( client_id=>'bureau_128');

Extrait d’un fichier de trace avec les évènements waits et binds

Voici un extrait d’un fichier de trace avec l’évènement 10046 (niveau 12 : variables attachées et évènements d’attentes).

Dans cet exemple la requête est la suivante :

SELECT CATEGORY, SEVERITY, FND_LOG_SEVERITY FROM FND_NEW_MESSAGES WHERE MESSAGE_NAME = :B1
AND APPLICATION_ID = :B2 AND LANGUAGE_CODE  = :B3 AND ROWNUM  = 1

PARSING IN CURSOR #91 len=157 dep=0 uid=47 oct=3 lid=47 tim=1096584531050607 hv=2850782796 ad='6244887c'
SELECT CATEGORY, SEVERITY, FND_LOG_SEVERITY FROM FND_NEW_MESSAGES WHERE MESSAGE_NAME = :B1
 AND APPLICATION_ID = :B2 AND LANGUAGE_CODE  = :B3 AND ROWNUM  = 1
END OF STMT
PARSE #91:c=0,e=27,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1096584531050599
BINDS #91:
 bind 0: dty=1 mxl=32(07) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=88 offset=0
   bfp=407abc30 bln=32 avl=07 flg=05
   value="EC_FROM"
 bind 1: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=0 offset=32
   bfp=407abc50 bln=22 avl=03 flg=01
   value=704
 bind 2: dty=1 mxl=32(02) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=0 offset=56
   bfp=407abc68 bln=32 avl=02 flg=01
   value="US"

EXEC #91:c=0,e=132,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1096584531050785
WAIT #91: nam='db file sequential read' ela= 38391 p1=21 p2=35217 p3=1
WAIT #91: nam='db file sequential read' ela= 32895 p1=21 p2=33279 p3=1
WAIT #91: nam='SQL*Net message to client' ela= 2 p1=1952673792 p2=1 p3=0
FETCH #91:c=0,e=71453,p=2,cr=4,cu=0,mis=0,r=1,dep=0,og=4,tim=1096584531122252
WAIT #91: nam='SQL*Net message from client' ela= 631 p1=1952673792 p2=1 p3=0
STAT #91 id=1 cnt=1 pid=0 pos=1 obj=0 op='COUNT STOPKEY '
STAT #91 id=2 cnt=1 pid=1 pos=1 obj=47435 op='TABLE ACCESS BY INDEX ROWID FND_NEW_MESSAGES '
STAT #91 id=3 cnt=1 pid=2 pos=1 obj=47524 op='INDEX UNIQUE SCAN FND_NEW_MESSAGES_PK '

Le fichier de trace donne alors clairement les valeurs des variables attachées indiquées par les mots clés bind 0, bind 1, bind 2, …. :

  • B1 = EC_FROM
  • B2 = 704
  • B3 = US

Les évènements d’attentes (db file sequential read, etc.) sont également affichés, le mot clé ela = 38391 donnant le temps d’attente en microsecondes sur l’évènement en question : WAIT #91: nam='db file sequential read' ela= 38391 p1=21 p2=35217 p3=1

Le binaire tkprof sur ce fichier de trace donne quant à lui les informations ci-dessous pour la requête prise en exemple ( attention : l’option aggregate=yes a été appliquée et cette requête a été exécutée trois fois ) :


SELECT CATEGORY, SEVERITY, FND_LOG_SEVERITY
FROM
 FND_NEW_MESSAGES WHERE MESSAGE_NAME = :B1 AND APPLICATION_ID = :B2 AND
  LANGUAGE_CODE  = :B3 AND ROWNUM  = 1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        3      0.00       0.00          0          0          0           0
Execute      3      0.00       0.00          0          0          0           0
Fetch        3      0.00       0.14          6         12          0           3
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        9      0.00       0.14          6         12          0           3

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 47  (APPS)

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  COUNT STOPKEY
      1   TABLE ACCESS BY INDEX ROWID FND_NEW_MESSAGES
      1    INDEX UNIQUE SCAN FND_NEW_MESSAGES_PK (object id 47524)

Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   GOAL: CHOOSE
      1   COUNT (STOPKEY)
      1    TABLE ACCESS   GOAL: ANALYZED (BY INDEX ROWID) OF
               'FND_NEW_MESSAGES'
      1     INDEX   GOAL: ANALYZED (UNIQUE SCAN) OF
                'FND_NEW_MESSAGES_PK' (UNIQUE)


Elapsed times include waiting on following events:

  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                         6        0.03          0.14
  SQL*Net message to client                       3        0.00          0.00
  SQL*Net message from client                     3       65.86         73.02

Dans ce paragraphe sont indiquées les statistiques des évènements d’attente sans à avoir à lire le fichier de trace lui même, cependant ceci est une nouveauté tkprof / Oracle 9i ( options waits=y de tkprof ), ce n’est pas disponible avec Oracle 8i.

Trace analyzer Oracle (TRCANLZR)

Oracle fournit quand même un outil TRCANLZR qui génère un rapport HTML sur l’interprétation des traces SQL avec les variables attachées et / ou évènements d’attente. Ce rapport reprend les informations contenues dans le rapport TKPROF en incluant d’autres données pertinentes comme :

  • I/O
  • Valeurs des variables attachées
  • Latches
  • Plans d’exécution
  • Statistiques CBO

Cet outil, disponible à partir d’Oracle 8i, n’est pas un binaire comme TKPROF mais tout comme STATSPACK, est un ensemble d’objets contenus dans un schéma : TRCANLZR. Cependant à l’instar de ce dernier, il peut être exécuté de n’importe quel autre schéma sans droit spécifique.

set serveroutput on ;
exec trca$i.trace_analyzer('sample_trcanlzr.trc') ;

Trace Analyzer sample_trcanlzr.html has been created in /Software/oracle/Instances/CLWU1ORA/udump

Voici un exemple de rapport généré : Exemple Trace Analyzer (HTML compressé)

Par défaut le rapport est généré dans le répertoire udump.

L’outil est téléchargeable à partir de Metalink (compte indispensable : http://metalink.oracle.com) : Note 224270.1. Il s’agit d’un fichier zip contenant les fichiers sql de création et de suppression ainsi que des fichiers exemples :

  • pour Oracle 9i et versions supérieures : trca.zip
  • pour Oracle 8i : trca_old.zip

L’installation est réalisée en exécutant le script tacreate.sql en tant que sysdba :

@tacreate.sql

Le fichier tacreate.sql créé un utilisateur appelé TRCANLZR avec tous les objets nécessaires :

  • les tables TRCA$
  • les indexes , séquences, vues et packages TRCA$I, TRCA$D.

Durant cette installation, le mot de passe est demandé ainsi que le tablespace temporaire et par défaut pour le user TRCANLZR.

@tacreate.sql

... Creating TRCA$ UDUMP Directory
... Creating TRCANLZR user ...
Choose the TRCANLZR user's password.
Not specifying a password will result in the installation FAILING

Specify TRCANLZR password
Entrez une valeur pour trcanlzr_password : trcanlzr
trcanlzr
Below are the list of online tablespaces in this database.
Decide which tablespace you wish to create the Trace Analyzer tables
and indexes. This will also be the TRCANLZR user's default tablespace.
Specifying the SYSTEM tablespace will result in the installation
FAILING, as using SYSTEM for tools data is not supported.

TABLESPACE_NAME                CONTENTS
------------------------------ ---------
TOOLS                          PERMANENT
TEMP                           PERMANENT
UNDO                           UNDO
USERS                          PERMANENT

Specify TRCANLZR user's default tablespace
Entrez une valeur pour default_tablespace : TOOLS
Using TOOLS for the default tablespace
Choose the TRCANLZR user's temporary tablespace.
Specifying the SYSTEM tablespace will result in the installation
FAILING, as using SYSTEM for the temporary tablespace is not recommended.
Specify TRCANLZR user's temporary tablespace.
Entrez une valeur pour temporary_tablespace : temp
Using temp for the temporary tablespace

Le script TACREATE.SQL appelle trois autres scripts, tacuser.sql, tactab.sql et tacpkg.sql.

Chaque script créé un fichier de sortie listant les différentes erreurs et dont l’extension est .lis

Voici un exemple du fichier tacpkg.lis (résultat du script qui crée les packages TRCA$D et TRCA$I):


Creating Package Specs trca$d...
Pas d'erreur.
Creating Package Body trca$d...
Pas d'erreur.
Creating Package Specs trca$i...
Pas d'erreur.
Creating Package Body trca$i..
Pas d'erreur.

NOTE:
TACPKG complete. Please check tacpkg.lis for any errors.

Si durant l’installation se produisent des erreurs, il est possible d’effectuer une désinstallation avant de relancer correctement l’installation grâce au script tadrop.sql fourni. 

@tadrop.sql