!
!
Info TAFORA
!
Méthodes Conseil
!
Mon credo Oracle
!
Nouveautés
!
Expertise technique
!
Fiches Techniques
!
Séminaires
Technique
FAQ
Domaines
DBA
Tuning
PL/SQL
Divers
Varia
Liens
Contact
TAFORA
Radu
Mail
Tuning avec l'événement 10046
Le noyau Oracle fournit des informations de très bas niveau si certaines interruptions lui sont imposées, interruptions appelées events. Un des events le plus profitable pour celui qui analyse les performances Oracle est l'event 10046. Cette interruption peut offrir de plus en plus d'informations en fonction du niveau de déboguage auquel elle est initialisée. Les résultats de cette action se retrouvent dans un fichier trace de la session qui est tracée. L'event 10046 présente à son niveau 1 les mêmes informations que présente l'option SQL_TRACE. A ses niveaux supérieurs, l'event 10046 fournit des informations concernant les attentes système rencontrées pendant l'exécution des divers ordres SQL, offrant des détails extrêmement intéressants sur le comportement système et permettant une fine analyse qui générera pratiquement immédiatement les bonnes résolutions concernant le tuning.
Tafora utilise très souvent les résultats de l'event 10046 pour dépister et optimiser les instructions SQL rebelles.


Niveaux de traçage de l'event 10046
10046 trace name context forever, level 1
Il a le même comportement que set SQL_TRACE ON, il trace les ordres SQL.
10046 trace name context forever, level 4
Même comportement que level 1 et montre les bind variables.
10046 trace name context forever, level 8
Même comportement que level 1 et montre les attentes
10046 trace name context forever, level 12
C'est une combinaison de level 4 et level 8

Activer et désactiver le traçage de l'event 10046
Pour tirer le meilleur profit de l'event 10046, plusieurs paramètres doivent convenir à ce traçage:
  • Le paramètre TIMED_STATISTICS doit être initialisé à TRUE pour la session analysée, sinon les compteurs de temps ne seront pas renseignés. Ce paramètre est renseigné soit dans init.ora (TIMED_STATISTICS=TRUE), modifié pour la session en cours (alter session set TIMED_STATISTICS=TRUE), ou modifié à distance (exec dbms_system).
  • Le fichier trace doit pouvoir contenir une grande quantité d'informations. La taille du fichier trace devrait être gérée avec le paramètre MAX_DUMP_FILE_SIZE (modifiable soit en init.ora soit avec alter session).
La désactivation de l'event 100046 se fait de la même manière que son activation ou en fermant tout simplement la session. Il est souhaitable que la session soit fermée pour clore le fichier de trace et vider tous les curseurs tracés. Arrêter une trace avec des curseurs ouverts (session en cours) peut légèrement fausser la trace.

Tracer la session courante
L'activation pour la session courante se fait avec :
alter session set timed_statistics=true;
alter session set max_dump_file_size=unlimited;
alter session set events '10046 trace name context forever, level 8';
La désactivation pour la session courante se fait avec :
alter session set events '10046 trace name context off';

Tracer une autre session
Pour tracer une autre session, nous devons identifier ses paramètres sid et serial# (dans V$SESSION) :
select  sid, serial#from v$session;
exec sys.dbms_system.set_bool_param_in_session(sid, serial#, 'timed_statistics', true);
exec sys.dbms_system.set_int_param_in_session(sid, serial#,'max_dump_file_size', 2147483647);
exec sys.dbms_system.set_ev(sid, serial#,10046, 8, '');
La désactivation de la trace de la session remote se fait avec:
exec sys.dbms_system.set_ev(sid, serial#,10046, 0, '');

Identifier le fichier de trace
Il n'existe pas une méthode infaillible pour dépister le nom du fichier trace pour toutes les plateformes, il convient de le chercher (fichier crée parmi les derniers, etc). Le fichier sera obligatoirement créé dans le répertoire indiqué par le paramètre USER_DUMP_DEST.

Interpréter le contenu du fichier trace
Pour la requête
SELECT COUNT(*) FROM (
  SELECT peres.nom, fils.prenom
    FROM  peres, fils
    WHERE  peres.id=fils.idpere
)    ;
Nous obtenons une trace de type
*** SESSION ID:(12.848) 2003-05-10 16:59:21.000
APPNAME mod='SQL*Plus' mh=3669949024 act='' ah=4029777240
  • mod Nom du module.
  • mh Valeur hash du module.
  • act Action.
  • ah Valeur hash de l'action. 
    • =====================
PARSING IN CURSOR #1 len=114 dep=0 uid=64 oct=3 lid=64 tim=9011124077 hv=3551157409 ad='3ff0364c'
  • len Longueur de l'instruction.
  • dep Profondeur récursive du curseur.
  • uid User id de l'utilisateur qui analyse le curseur.
  • oct Type de commande Oracle.
  • lid User id du privilège.
  • tim Timestamp. Mesuré en centisecondes avant 9i, il l'est en microsecondes depuis 9i. Il permet de mesurer les durées absolues des traitements.
  • hv Identifiant du hash
  • ad Adresse de la commande (Présente dans V$SQLAREA et V$SQLTEXT). 
    • SELECT COUNT(*) FROM (
  SELECT peres.nom, fils.prenom
    FROM  peres, fils
    WHERE  peres.id=fils.idpere
)    
END OF STMT
  • L'instruction SQL elle-meme. 
    • PARSE #1:c=0,e=124,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=9011124063
EXEC #1:c=0,e=163,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=9011126012
WAIT #1: nam='SQL*Net message to client' ela= 7 p1=1413697536 p2=1 p3=0
FETCH #1:c=593750,e=583031,p=0,cr=230,cu=0,mis=0,r=1,dep=0,og=4,tim=9011709627
WAIT #1: nam='SQL*Net message from client' ela= 770 p1=1413697536 p2=1 p3=0
FETCH #1:c=0,e=4,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=9011712461
WAIT #1: nam='SQL*Net message to client' ela= 5 p1=1413697536 p2=1 p3=0
WAIT #1: nam='SQL*Net message from client' ela= 4893 p1=1413697536 p2=1 p3=0
XCTEND rlbk=0, rd_only=1
    Les lignes XCTEND marquent la fin d'une transaction.
    • rlbk est à 1 si un rollback a été effectué, 0 dans le cas contraire.
    • rd_only est à zero si des modification ont étés effectuées, 1 sinon.
    Les lignes PARSE, EXEC, FETCH sont celles connues : interpréter une commande, l'exécuter, récupérer une ligne d'un curseur.
    • c temps CPU time (centièmes de seconde).
    • e temps elapsed (centièmes de seconde).
    • p lectures physiques.
    • cr buffers lu en mode consistent.
    • cu buffers lus en mode courant.
    • mis curseurs non trouvés dans le cache.
    • r nombre de lignes.
    • dep profondeur de la récursivité (0 = ordre courant, 1 et plus = appel récursif).
    • og optimizeur: 1=All_Rows, 2=First_Rows, 3=Rule, 4=Choose
    • tim timestamp (centièmes de seconde). Base pour mesurer le temps passé entre deux actions. 
    STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=230 r=0 w=0 time=582996 us)'
STAT #1 id=2 cnt=30000 pid=1 pos=1 obj=0 op='MERGE JOIN  (cr=230 r=0 w=0 time=550441 us)'
STAT #1 id=3 cnt=30000 pid=2 pos=1 obj=0 op='SORT JOIN (cr=184 r=0 w=0 time=268162 us)'
STAT #1 id=4 cnt=30000 pid=3 pos=1 obj=48894 op='TABLE ACCESS FULL OBJ#(48894) (cr=184 r=0 w=0 time=48221 us)'
STAT #1 id=5 cnt=30000 pid=2 pos=2 obj=0 op='SORT JOIN (cr=46 r=0 w=0 time=142131 us)'
STAT #1 id=6 cnt=10000 pid=5 pos=1 obj=48893 op='TABLE ACCESS FULL OBJ#(48893) (cr=46 r=0 w=0 time=15499 us)'
    Les lignes stat constituent la source pour l'explain plan interprété.
    WAIT #1: nam='SQL*Net message to client' ela= 7 p1=1413697536 p2=1 p3=0
    Les lignes WAIT nous informent des attentes système pour le curseur en cause:
    • Nam L'objet attendu. Les mêmes information étaient présentes lors de l'exécution dans la vue V$SESSION_WAIT.
    • Ela Temps passé pour l'opération.
    • p1,p2,p3 sont ceux connus.
    Bien que TKPROF sait lire une partie du fichier généré, vous devriez interpréter complètement le fichier de trace généré, vous aurez le plus technique regard sur le déroulement de votre production.
    Notions complémentaires
    *** SESSION ID:(12.848) 2003-05-10 16:59:21.000
    Oracle met cette information quand il mesure plus de quelques dizaines de secondes entre différentes lignes de trace. Cette information (***) aide à calibrer la mesure du temps Oracle (tim) avec la mesure du temps OS Le timestamp est évalué immédiatement avant la ligne *** (immédiatement après la notification antérieure de trace). Le noyau Oracle émet une ligne *** après un laps de temps important (dizaines de secondes) écoulé depuis la dernière information tracée, donc dans des cas des gros WAITs qui induisent des gros attentes réelles (ela) sans mesure interne (tim). Il est possible de forcer l’apparition d’une ligne semblable avec un appel de exec DBMS_SYSTEM.KSDDDT.
    Lectures supplémentaires
    Il existe de très intéressantes notes concernant l'interprétation de l'event 10046, notamment chez
    Anjo Kolk, www.hotsos.com et sur le site Metalink.
    Copyright © 1998-2002 Radu Caulea, TAFORA MAJ 06/11/2006 !
    Commentaires et suggestions radu[CHEZ]tafora.fr