Ce sont ces informations qui vont nous permettre d'analyser les problèmes de performance d'une application donnée.
Ce fichier trace généré est un peu compliqué à étudier dans son format brute. L'utilitaire TKPROF a justement pour but de générer un rapport à partir de ce fichier pour le rendre plus lisible.
Voyons d'abord comment générer une trace SQL 10046.
Pour activer le tracing au niveau de ma session j'utilise en générale les commandes suivantes:
ALTER SESSION SET timed_statistics = TRUE; ALTER SESSION SET max_dump_file_size = unlimited; ALTER SESSION SET TRACEFILE_IDENTIFIER = 'Ahmed_10046_sql_trace'; ALTER SESSION SET events '10046 trace name context forever, level 12';
Par défaut le paramètre TIMED_STATISTICS est à TRUE mais par sécurité je l'active au niveau session au cas où ce paramètre ait été désactivé au niveau de l'instance.
Le paramètre MAX_DUMP_FILE_SIZE détermine la taille maximale que peut atteindre le fichier trace. Je le met à UNLIMITED au cas où au niveau de la base le DBA ait mis une valeur limite insuffisante.
Pour pouvoir retrouver facilement mon fichier trace je modifie également la valeur du TRACEFILE_IDENTIFIER. Le nom du fichier de trace généré contiendra ainsi en partie ce que j'ai mis comme valeur pour ce paramètre.
La dernière commande active le tracing de ma session. Le paramètre LEVEL à 12 indique que je souhaite tracer les wait events ainsi que les informations au niveau des bind variables.
Exemple:
D:\oracle\product\11.2.0>sqlplus scott/tiger SQL*Plus: Release 11.2.0.1.0 Production on Lun. Janv. 17 17:53:08 2011 Copyright (c) 1982, 2010, Oracle. All rights reserved. Connecté à : Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - Production With the Partitioning, OLAP, Data Mining and Real Application Testing options SQL> drop table t1 purge; Table supprimée. SQL> create table t1 as select rownum num,a.* from dba_objects a; Table créée. SQL> ALTER SESSION SET TRACEFILE_IDENTIFIER = 'Ahmed_10046_sql_trace'; Session modifiée. SQL> ALTER SESSION SET timed_statistics = TRUE; Session modifiée. SQL> ALTER SESSION SET max_dump_file_size = unlimited; Session modifiée. SQL> ALTER SESSION SET events '10046 trace name context forever, level 12'; Session modifiée. SQL> declare 2 v_row_t1 t1%rowtype; 3 begin 4 5 for i in 1..100 6 loop 7 select * into v_row_t1 from t1 where num=i; 8 end loop; 9 10 end; 11 / Procédure PL/SQL terminée avec succès. SQL> ALTER SESSION SET events '10046 trace name context off'; Session modifiée.La dernière commande ci-dessus permet de désactiver le tracing.
Je peux maintenant aller récupérer mon fichier trace qui se trouve dans le répertoire définie par le paramètre USER_DUMP_DEST:
SQL> sho parameter user_dump
NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
user_dump_dest string d:\oracle\product\11.2.0\diag\
rdbms\orclp850\orclp850\trace
Voyons un extrait du contenu de la trace "brute de pomme"
PARSING IN CURSOR #4 len=31 dep=1 uid=84 oct=3 lid=84 tim=3649721690252 hv=3779410954 ad='221a3fa8' sqlid='ask3fx3hnag0a' SELECT * FROM T1 WHERE NUM=:B1 END OF STMT BINDS #4: Bind#0 oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00 oacflg=03 fl2=206001 frm=00 csi=00 siz=24 off=0 kxsbbbfp=0f19c50c bln=22 avl=02 flg=05 value=2 EXEC #4:c=0,e=195,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=3617692013,tim=3649721690403 WAIT #4: nam='direct path read' ela= 591 file number=4 first dba=531 block cnt=13 obj#=74591 tim=3649721691313 WAIT #4: nam='direct path read' ela= 869 file number=4 first dba=545 block cnt=15 obj#=74591 tim=3649721692358 WAIT #4: nam='direct path read' ela= 488 file number=4 first dba=561 block cnt=15 obj#=74591 tim=3649721692995 WAIT #4: nam='direct path read' ela= 466 file number=4 first dba=577 block cnt=15 obj#=74591 tim=3649721693619 WAIT #4: nam='direct path read' ela= 445 file number=4 first dba=593 block cnt=15 obj#=74591 tim=3649721694261 WAIT #4: nam='direct path read' ela= 494 file number=4 first dba=609 block cnt=15 obj#=74591 tim=3649721694905 WAIT #4: nam='direct path read' ela= 449 file number=4 first dba=625 block cnt=15 obj#=74591 tim=3649721695551 WAIT #4: nam='direct path read' ela= 368 file number=4 first dba=641 block cnt=15 obj#=74591 tim=3649721696094 WAIT #4: nam='direct path read' ela= 19977 file number=4 first dba=770 block cnt=30 obj#=74591 tim=3649721716234 WAIT #4: nam='direct path read' ela= 2939 file number=4 first dba=800 block cnt=32 obj#=74591 tim=3649721719585 WAIT #4: nam='direct path read' ela= 4390 file number=4 first dba=832 block cnt=32 obj#=74591 tim=3649721724244 WAIT #4: nam='direct path read' ela= 3115 file number=4 first dba=864 block cnt=32 obj#=74591 tim=3649721727616 WAIT #4: nam='direct path read' ela= 3090 file number=4 first dba=898 block cnt=30 obj#=74591 tim=3649721730985 WAIT #4: nam='direct path read' ela= 4408 file number=4 first dba=928 block cnt=32 obj#=74591 tim=3649721735640 WAIT #4: nam='direct path read' ela= 3124 file number=4 first dba=960 block cnt=32 obj#=74591 tim=3649721739013 WAIT #4: nam='direct path read' ela= 4385 file number=4 first dba=992 block cnt=32 obj#=74591 tim=3649721743674 WAIT #4: nam='direct path read' ela= 3140 file number=4 first dba=1026 block cnt=30 obj#=74591 tim=3649721747073 WAIT #4: nam='direct path read' ela= 4169 file number=4 first dba=1056 block cnt=32 obj#=74591 tim=3649721751712 WAIT #4: nam='direct path read' ela= 3051 file number=4 first dba=1088 block cnt=32 obj#=74591 tim=3649721755071 WAIT #4: nam='direct path read' ela= 3120 file number=4 first dba=1120 block cnt=32 obj#=74591 tim=3649721758446 WAIT #4: nam='direct path read' ela= 4396 file number=4 first dba=1154 block cnt=30 obj#=74591 tim=3649721763115 WAIT #4: nam='direct path read' ela= 3126 file number=4 first dba=1184 block cnt=32 obj#=74591 tim=3649721766486 WAIT #4: nam='direct path read' ela= 4406 file number=4 first dba=1216 block cnt=32 obj#=74591 tim=3649721771141 WAIT #4: nam='direct path read' ela= 3113 file number=4 first dba=1248 block cnt=32 obj#=74591 tim=3649721774514 WAIT #4: nam='direct path read' ela= 3123 file number=4 first dba=1282 block cnt=30 obj#=74591 tim=3649721777891 WAIT #4: nam='direct path read' ela= 4416 file number=4 first dba=1312 block cnt=32 obj#=74591 tim=3649721782548 WAIT #4: nam='direct path read' ela= 3106 file number=4 first dba=1344 block cnt=32 obj#=74591 tim=3649721785917 WAIT #4: nam='direct path read' ela= 4400 file number=4 first dba=1376 block cnt=32 obj#=74591 tim=3649721790574 WAIT #4: nam='direct path read' ela= 3102 file number=4 first dba=1410 block cnt=30 obj#=74591 tim=3649721793944 WAIT #4: nam='direct path read' ela= 3141 file number=4 first dba=1440 block cnt=32 obj#=74591 tim=3649721797323 WAIT #4: nam='direct path read' ela= 4367 file number=4 first dba=1472 block cnt=32 obj#=74591 tim=3649721801989 WAIT #4: nam='direct path read' ela= 3024 file number=4 first dba=1504 block cnt=32 obj#=74591 tim=3649721805349 WAIT #4: nam='direct path read' ela= 4409 file number=4 first dba=1538 block cnt=30 obj#=74591 tim=3649721810028 WAIT #4: nam='direct path read' ela= 3098 file number=4 first dba=1568 block cnt=32 obj#=74591 tim=3649721813378 WAIT #4: nam='direct path read' ela= 3104 file number=4 first dba=1600 block cnt=32 obj#=74591 tim=3649721816745 WAIT #4: nam='direct path read' ela= 4439 file number=4 first dba=1632 block cnt=32 obj#=74591 tim=3649721821436 WAIT #4: nam='direct path read' ela= 3087 file number=4 first dba=1666 block cnt=30 obj#=74591 tim=3649721824781 WAIT #4: nam='direct path read' ela= 4384 file number=4 first dba=1696 block cnt=32 obj#=74591 tim=3649721829436 WAIT #4: nam='direct path read' ela= 1773 file number=4 first dba=1728 block cnt=19 obj#=74591 tim=3649721831424 FETCH #4:c=31250,e=141113,p=1081,cr=1084,cu=0,mis=0,r=1,dep=1,og=1,plh=3617692013,tim=3649721831583 CLOSE #4:c=0,e=5,dep=1,type=3,tim=3649721831678 =====================
Vous constatez qu'il s'agit d'une partie de la trace concernant l'exécution de la requête "SELECT * FROM T1 WHERE NUM=:B1" pour la valeur NUM=2 (voir partie intitulé BINDS). L'attente pour cette exécution concerne les accès disques. "DIRECT PATH READ" indique qu'il s'agit d'accès disques en mode direct c'est à dire sans passer par le buffer cache. En 10g j'aurais eu plutôt du "DB_FILE SCATTERED READ". Ce test valide bien qu'en 11g Oracle peut faire du direct I/O pour les accès multi-blocks (fast table scan, fast full index scan)..
On voit aussi que la plupart du temps 32 blocks sont récupérées par I/O (block cnt=32), ça match bien avec la valeur de mon paramètre DB_FILE_MULTIBLOCK_READ_COUNT qui est positionné à 32 sur ma base.
Maintenant générons le rapport TKPROF pour ce fichier trace:
TKPROF orclp850_ora_3588_Ahmed_10046_sql_trace.trc TKPROF_REPORT_17012011.txt sort=exeela aggregate=YES
Le premier paramètre correspond au nom du fichier trace qu'on veut traiter. Le 2ème paramètre correspond au nom qu'on veut donner au fichier TKPROF de sortie.
Le paramètre SORT indique la manière dont on veut que les requêtes SQL dans le rapport TKPROF soient triées. Ici il s'agit d'un tri par temps consommé pour la phase EXECUTION.
Le paramètre AGGREGATE indique si l'on veut aggréger les requêtes identiques ou pas.
Vous pouvez afficher la liste de tous les paramètres disponibles en tapant la commande TKPROF sans paramètres:
D:\oracle\product\11.2.0>tkprof
Usage: tkprof tracefile outputfile [explain= ] [table= ]
[print= ] [insert= ] [sys= ] [sort= ]
table=schema.tablename Use 'schema.tablename' with 'explain=' option.
explain=user/password Connect to ORACLE and issue EXPLAIN PLAN.
print=integer List only the first 'integer' SQL statements.
aggregate=yes|no
insert=filename List SQL statements and data inside INSERT statements.
sys=no TKPROF does not list SQL statements run as user SYS.
record=filename Record non-recursive statements found in the trace file.
waits=yes|no Record summary for any wait events found in the trace file.
sort=option Set of zero or more of the following sort options:
prscnt number of times parse was called
prscpu cpu time parsing
prsela elapsed time parsing
prsdsk number of disk reads during parse
prsqry number of buffers for consistent read during parse
prscu number of buffers for current read during parse
prsmis number of misses in library cache during parse
execnt number of execute was called
execpu cpu time spent executing
exeela elapsed time executing
exedsk number of disk reads during execute
exeqry number of buffers for consistent read during execute
execu number of buffers for current read during execute
exerow number of rows processed during execute
exemis number of library cache misses during execute
fchcnt number of times fetch was called
fchcpu cpu time spent fetching
fchela elapsed time fetching
fchdsk number of disk reads during fetch
fchqry number of buffers for consistent read during fetch
fchcu number of buffers for current read during fetch
fchrow number of rows fetched
userid userid of user that parsed the cursor
Voyons maintenant ce que contient le rapport TKPROF pour notre exemple.
L'en-tête du fichier contient les informations suivantes:
TKPROF: Release 11.2.0.1.0 - Development on Mar. Janv. 18 10:44:51 2011 Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved. Trace file: orclp850_ora_3588_Ahmed_10046_sql_trace.trc Sort options: exeela ******************************************************************************** count = number of times OCI procedure was executed cpu = cpu time in seconds executing elapsed = elapsed time in seconds executing disk = number of physical reads of buffers from disk query = number of buffers gotten for consistent read current = number of buffers gotten in current mode (usually for update) rows = number of rows processed by the fetch or execute call ********************************************************************************On a des informations sur la version de la base, le nom du fichier trace utilisé pour ce rapport, l'option SORT utilisé et une définition des indicateurs qu'on retrouvera dans le rapport. Par exemple on voit que l'indicateur DISK correpsond au nombre d'I/O effectués pour une requête.
La suite du rapport nous donne les informations sur la requête qu'on a exécuté 100 fois dans notre exemple précédent:
SQL ID: ask3fx3hnag0a
Plan Hash: 3617692013
SELECT *
FROM
T1 WHERE NUM=:B1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 100 0.04 0.03 0 1 0 0
Fetch 100 1.53 21.57 108100 108400 0 100
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 201 1.57 21.60 108100 108401 0 100
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 84 (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS FULL T1 (cr=1084 pr=1081 pw=0 time=0 us cost=303 size=2640 card=12)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
reliable message 1 0.00 0.00
enq: KO - fast object checkpoint 1 0.00 0.00
direct path read 3843 0.26 19.77
asynch descriptor resize 96 0.00 0.00
********************************************************************************
Section "statistiques d'exécution"
call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 100 0.04 0.03 0 1 0 0 Fetch 100 1.53 21.57 108100 108400 0 100 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 201 1.57 21.60 108100 108401 0 100Les lignes du tableau correspondent aux 3 phases d'une requête SQL:
- Parsing: phase durant laquelle le plan d'exécution est calculé
- Execute: phase durant laquelle la requête est exécutée (concerne surtout les requêtes DML)
- Fetch: phase durant laquelle les lignes désirées sont retournées (concerne surtout les requêtes SELECT)
Pour chacune de ces phases on a des informations sur le temps total consommé (colonne ELAPSED), le temps CPU consommé (colonne CPU), le nombre de lectures physiques (colonne DISK), le nombre de
lectures logiques (colonne QUERY+CURRENT) et le nombre de lignes traitées (colonne ROWS).
Dans notre exemple on voit que la requête n'a été parsée qu'une seule fois (COUNT pour PARSE = 1) pour 100 exécutions (COUNT pour EXECUTE = 100). Si on avait un "count pour PARSE" de 100 pour 100 exécutions ça aurait clairement mis en évidence une défaillance au niveau de l'utilisation des variables bindées dans notre application.
On voit aussi que les 100 requêtes se sont exécutées en 26.6 secondes dont 1.57 sec correspond à du temps CPU. Le reste correspond au temps d'attente qu'on retrouve plus bas dans la partie "EVENT WAITED ON".
Section "plan d'exécution"
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS FULL T1 (cr=1084 pr=1081 pw=0 time=0 us cost=303 size=2640 card=12)
Après le tableau des statistiques d'exécution on retrouve le plan réellement utilisé au moment de l'exécution de la requête avec un certain nombre d'informations:- ROWS: correspond aux lignes réellement traitées à chaque opération du plan
- CR: correspond aux nombre de logical reads.
- PR: correspond aux nombre de physical reads.
- PW: correspond aux nombre de physical writes.
- TIME: correspond au temps passé sur cette opération en micro-secondes
- COST= correspond au coût pour cette opération
- SIZE: correspond au nombre d'octects traités lors de cette operation.
- CARD: correspond au nombre de lignes estimées par le CBO.
En comparant les lignes réellement processées (ROWS) et le nombre de lignes estimées par le CBO (card) on peut facilement détecter quelle est la partie du plan où l'optimiseur s'est trompé.
A noter aussi que les statistiques sont celles pour une seule exécution, c'est pour cela que le nombre de physical reads est de 1081 (=108401/100).
Section "évènements d'attente"
Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ reliable message 1 0.00 0.00 enq: KO - fast object checkpoint 1 0.00 0.00 direct path read 3843 0.26 19.77 asynch descriptor resize 96 0.00 0.00Après le plan d'exécution on peut voir la liste des évènements d'attente associés à l'exécution de cette requête. On note ici que sur 21.6 secondes Oracle a passé 19.77 secondes sur de l'attente d'I/O.
Pour chaque wait event on retrouve les informations suivantes:
- Times Waited: Nombre de fois où on a attendu sur cet évènement
- Max. Wait: Temps d'attente maximal constaté pour cet évènement
- Total Waited: Temps total en secondes constaté pour cet évènement
Ensuite pour chaque requête on retrouvera les mêmes sections que je viens de décrire à savoir: tableau des stats d'exécution, plan réel d'exécution et détail des temps d'attente.
A la fin du rapport on retrouve le total des statistiques collectées dans la trace:
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 2 0.00 0.01 0 3 0 0 Execute 2 0.03 0.03 0 108509 0 1 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 4 0.03 0.05 0 108512 0 1 Misses in library cache during parse: 1 Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message to client 2 0.00 0.00 SQL*Net message from client 2 110.55 113.51 OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 4 0.01 0.00 0 0 0 0 Execute 119 0.04 0.03 0 1 0 0 Fetch 135 1.56 21.82 108453 108511 0 117 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 258 1.62 21.86 108453 108512 0 117 Misses in library cache during parse: 2 Misses in library cache during execute: 1 Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ db file scattered read 43 0.02 0.16 db file sequential read 11 0.01 0.03 reliable message 1 0.00 0.00 enq: KO - fast object checkpoint 1 0.00 0.00 direct path read 3843 0.26 19.77 asynch descriptor resize 96 0.00 0.00 103 user SQL statements in session. 18 internal SQL statements in session. 121 SQL statements in session.
On constate que les requêtes récursives et non récursives correspondent à 2 sections distinctes.
CONCLUSION:
Un rapport TKPROF à partir d'une trace 10046 est d'une aide inestimable pour analyser les problèmes de performances. Il peut nous aider à mettre en évidence les requêtes les plus consommatrices, les problèmes de hard parses, les évènements d'attentes les plus importants. Il permet aussi d'avoir pour chaque requête le plan réellement exécuté avec les cardinalités réellement processées pour chaque opération. Aussi et surtout c'est un outil gratuit. Il peut donc être utilisé sur n'importe quelle base même si vous n'avez pas payé de licence diagnostic pack ou tuning pack.
