Analyse de la trace Oracle

Free Sample Premium Proxy List 08:05
L'opération précédente a généré un fichier de cette forme :
Fichier trace
Sélectionnez
Oracle9i Enterprise Edition Release 9.2.0.5.0 - 64bit Production
With the Partitioning option
JServer Release 9.2.0.5.0 - Production
ORACLE_HOME = /oracle
System name:    AIX
Node name:      oraserver
Release:        2
Version:        5
Machine:        0026510C4C00
Instance name: orafrance
Redo thread mounted by this instance: 1
Oracle process number: 48
Unix process pid: 2961508, image: oracle@oraserver (TNS V1-V3)

*** 2005-06-07 11:00:33.056
*** SESSION ID:(51.13) 2005-06-07 11:00:32.994
WAIT #1: nam='pipe get' ela= 2517030 p1=504403158592102776 p2=4096 p3=20
WAIT #1: nam='pipe get' ela= 1000024 p1=504403158592102776 p2=4096 p3=20
APPNAME mod='01@</appl/glb/4.0.0/sql/GLBSUBMIT.sql' mh=1035094561 act
='' ah=4029777240
=====================
PARSING IN CURSOR #25 len=715 dep=1 uid=173 oct=3 lid=173 tim=1091928548919953 h
v=2807191513 ad='1379eed0'
SELECT IR1.GROUP_REQUEST_ID,MIN(IR1.GROUP_ORDER_NUM) ORDRE FROM JEFB_CONC_INST_R
EQUESTS IR1 WHERE IR1.PHASE_CODE = 'I' AND ( (IR1.FORCE_RUN = 'N' AND NOT EXISTS
 (SELECT 'requete precedente non terminee ou en erreur' FROM JEFB_CONC_INST_REQU
ESTS IR2 WHERE IR2.GROUP_REQUEST_ID = IR1.GROUP_REQUEST_ID AND IR2.GROUP_ORDER_N
UM < IR1.GROUP_ORDER_NUM AND ( IR2.PHASE_CODE <> 'C' OR (IR2.PHASE_CODE = 'C' AN
D IR2.STATUS_CODE NOT IN ('C','I','R')) ))) OR (IR1.FORCE_RUN = 'Y' AND NOT EXIS
TS (SELECT 'requete precedente en cours' FROM JEFB_CONC_INST_REQUESTS IR2 WHERE
IR2.GROUP_REQUEST_ID = IR1.GROUP_REQUEST_ID AND IR2.GROUP_ORDER_NUM < IR1.GROUP_
ORDER_NUM AND IR2.PHASE_CODE IN ('P','R'))) ) GROUP BY IR1.GROUP_REQUEST_ID
END OF STMT
EXEC #25:c=0,e=108,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1091928548919919
FETCH #25:c=0,e=57,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,tim=1091928548922291
XCTEND rlbk=0, rd_only=1
=====================
PARSING IN CURSOR #27 len=6 dep=1 uid=173 oct=44 lid=173 tim=1091928548922410 hv
=1053795750 ad='125e3f68'
COMMIT
END OF STMT
EXEC #27:c=0,e=48,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1091928548922408
WAIT #1: nam='pipe get' ela= 2000021 p1=504403158592102776 p2=4096 p3=20
WAIT #1: nam='pipe get' ela= 3000027 p1=504403158592102776 p2=4096 p3=20
WAIT #1: nam='pipe get' ela= 4000026 p1=504403158592102776 p2=4096 p3=20
WAIT #1: nam='pipe get' ela= 5000029 p1=504403158592102776 p2=4096 p3=20
WAIT #1: nam='pipe get' ela= 5000021 p1=504403158592102776 p2=4096 p3=20
WAIT #1: nam='pipe get' ela= 1000017 p1=504403158592102776 p2=4096 p3=20
EXEC #25:c=0,e=79,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1091928568923249
FETCH #25:c=0,e=30,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,tim=1091928568923330
XCTEND rlbk=0, rd_only=1
EXEC #27:c=0,e=44,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1091928788936635
WAIT #1: nam='pipe get' ela= 2000021 p1=504403158592102776 p2=4096 p3=20
WAIT #1: nam='pipe get' ela= 3000021 p1=504403158592102776 p2=4096 p3=20
WAIT #1: nam='pipe get' ela= 4000020 p1=504403158592102776 p2=4096 p3=20
WAIT #1: nam='pipe get' ela= 5000023 p1=504403158592102776 p2=4096 p3=20
WAIT #1: nam='pipe get' ela= 5000021 p1=504403158592102776 p2=4096 p3=20
WAIT #1: nam='pipe get' ela= 1000019 p1=504403158592102776 p2=4096 p3=20
EXEC #25:c=0,e=88,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1091928808937449
FETCH #25:c=0,e=39,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,tim=1091928808937541
XCTEND rlbk=0, rd_only=1
EXEC #27:c=0,e=45,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1091928808937641
WAIT #1: nam='pipe get' ela= 2000021 p1=504403158592102776 p2=4096 p3=20
Je ne rentrerais pas trop dans les détails puisque nous verrons dans l'article suivant comment lire plus facilement ce résultat. Néanmoins, il n'est pas inintéressant de savoir interpréter un minimum cette trace.
L'entête récapitule les données du système : OS, nom de l'instance, nom du serveur, etc…
Ligne du fichier Description
*** SESSION ID:(51.13) 2005-06-07 11:00:32.994 Indique le SID et SERIAL# de la session tracée et l'heure de début de la trace
APPNAME mod='01@</appl/glb/4.0.0/sql/GLBSUBMIT.sql' mh=1035094561 act ='' ah=4029777240 C'est le script /appl/glb/4.0.0/sql/GLBSUBMIT.sql qui est en cours
=====================
PARSING IN CURSOR #25 len=715 dep=1 uid=173 oct=3 lid=173 tim=1091928548919953 h v=2807191513 ad='1379eed0' 		Le curseur 25 (id interne) est en cours de parsing (phase d'analyse de la requête). Ce curseur traite la requête SQL qui suit ces lignes jusqu'à la ligne END OF STMT
EXEC #25:c=0,e=108,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1091928548919919
FETCH #25:c=0,e=57,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,tim=1091928548922291 XCTEND rlbk=0, rd_only=1 		Phase execute et fetch (exécution de la requête et restitution du résultat).
WAIT #1: nam='pipe get' ela= 2000021 p1=504403158592102776 p2=4096 p3=20 Événement d'attente pipe get sur le cursor 1.
Je n'ai pas parlé de la signification des variables c ou e dont on peut lire les valeurs.
Voila une liste de ce qu'elles indiquent :
  • Liste des indicateurs
  1. c =>temps cpu en centième de seconde
  2. e =>temps total en centième de seconde
  3. p => nombre de lectures sur disque
  4. (cr + cu) => nombre buffers gets
  5. r => nombre de lignes retournées
  6. og => mode de l'optimiseur : 4 => CHOOSE
Ainsi la ligne :
EXEC #25:c=0,e=108,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1091928548919919
Indique une exécution qui n'a pas consommé de temps processeur mais qui a duré 108cs (1s).

Ici l'extrait de trace est suffisamment peu fournit pour admettre une lecture. Mais il est très difficile de lire un fichier trace exhaustif. Heureusement, Oracle fournit un outil pour formater ce fichier pour faciliter la lecture,
Reactions

Enregistrer un commentaire

0 Commentaires