J’ai été destinataire d’un fichier de trace TKPROF correspondant à une requête qui ne s’exécutait pas en un temps acceptable. Le but de cet article est de faire un résumé, étape par étape, de mes investigations relatives à la compréhension de ce problème de performance via l’analyse et l’interprétation de ce fichier TKPROF.
Tout d’abord, que pouvons-nous diagnostiquer en lisant la partie suivante extraite de ce fichier TKPROF ?
call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 2 0.02 0.02 0 0 0 0 Execute 2 0.00 0.00 0 0 0 0 Fetch 44 34.35 420.94 132860 161300 0 624 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 48 34.37 420.96 132860 161300 0 624 Misses in library cache during parse: 1 Optimizer mode: ALL_ROWS Parsing user id: 122
Rien?
Pas vraiment. Plusieurs informations cruciales peuvent être déjà déduites des quelques lignes qui précèdent :
1. Nous avons grosso-modo le même nombre de lectures physiques (132860) que de lectures logiques (lectures à partir de la mémoire, 161300). Ceci est un symptôme de (et un pointer vers) la présence de selects agressifs (FULL TABLE SCAN) sur des tables qui doivent être examinés de plus prêt.
2. Il existe une grande différence entre le temps total consommé par la requête (elapsed : 420,96 s) et le temps consommé par la machine (CPU 34,37). Ceci veut dire que la requête a passé un bon moment dans l’attente de quelque chose que nous devons identifier.
3. La requête a utilisé un grand nombre de lectures physiques et logiques pour, à la fin, ne générer qu’un nombre très limité de lignes(624). Ce qui veut dire que la requête a commencé par manipuler un grand nombre de lignes pour enfin laisser tomber la quasi-totalité de ce volume initial. Ceci contredit un principe fondamental de la performance des requêtes ”commencer petit (volume de données) et restez petit”
4. Il y a un ”miss in Library cache during parse” qui indique la présence d’un ”hard parse” lors de l’exécution de la requête.
Avez vous noté combien d’information avons nous glanées simplement en interprétant les 4 premières lignes du fichier TKPROF ? En fait, il existe encore un point fondamental que l’on peut déduire de ces 4 lignes mais que je préfère ignorer à ce stade de l’article. J’y reviendrai dans un moment
Continuons notre investigation en abordant la partie suivante du fichier TKPROF.
Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message to client 46 0.00 0.00 SQL*Net message from client 46 128.81 387.60 db file scattered read 4844 1.28 387.95 db file sequential read 76 0.72 1.89
Que pouvons-nous extraire des lignes précédentes:
Rien?
Par vraiment. Oracle a passé 387,95 secondes générant les données via un accès ”full table scan” (db file scattered read, rappelez-vous de ce que j’ai mentionné plus haut à propos du nombre élevé de lectures physiques) et 387,60 secondes en attente que le client finisse de rapatrier ce qu’il a demandé (SQL*Net message from client) via 46 paquets (Times Waited) de 15 enregistrements chacun.
Vous vous demandez peut-être comment j’ai fait pour trouver que les 46 paquets de données sont formés de 15 enregistrements chacun? C’est l’information que je pouvais avoir dès le début du fichier trace et que j’ai préférée garder sous silence jusqu’à maintenant.
call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 2 0.02 0.02 0 0 0 0 Execute 2 0.00 0.00 0 0 0 0 Fetch 44 34.35 420.94 132860 161300 0 624 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 48 34.37 420.96 132860 161300 0 624
Oracle a généré 624 lignes via 2 exécutions en utilisant 44 fetches :
rows/Fetch = 624/44=14,18 ~ 15
Ce nombre représente la valeur par défaut du paramètre ”arraysize” utilisé pour échanger de l’information entre le client et le serveur.
Observons bien: le temps consommé par Oracle générant les données est égal au temps qu’a nécessité le rapatriement de ces mêmes données vers le client !!! Ceci est un symptôme d’un problème au niveau de l’activité du réseau. Si on change le paramètre ”arraysize” de sa valeur par défaut 15 à une valeur plus élevée il se pourrait alors que le temps de réponse total de la requête s’améliore. Charles Hooper a écrit un article très intéressant à ce sujet.
Avez-vous réalisé combien d’informations avons-nous rassemblées jusqu’à présent ? Et rappelez-vous nous n’avons pas encore vu à quoi ressemble le texte de la requête !!!
Continuons nos investigations de ce fichier TKPROF. Que pouvons nous identifier avec la partie ”row source” ou la partie présentant le plan d’exécution reproduit ci-dessous:
Rows Row Source Operation
------- ---------------------------------------------------
312 HASH JOIN OUTER (cr=80650 pr=66430 pw=0 time=216,681,765 us)
312 VIEW (cr=40325 pr=33215 pw=0 time=114,999,408 us)
312 MERGE JOIN CARTESIAN (cr=40325 pr=33215 pw=0 time=114,999,403 us)
26 VIEW (cr=40325 pr=33215 pw=0 time=114,998,980 us)
26 HASH GROUP BY (cr=40325 pr=33215 pw=0 time=114,998,974 us)
19827 HASH JOIN SEMI (cr=40325 pr=33215 pw=0 time=114,911,666 us)
45426 PARTITION RANGE SINGLE PARTITION: 10 10 (cr=33455 pr=33215 pw=0 time=112,077,047 us)
45426 TABLE ACCESS FULL ORDERS_MANAGMENTS PARTITION: 10 10 (cr=33455 pr=33215 pw=0 time=112,031,597 us)
1721227 PARTITION RANGE SINGLE PARTITION: 3 3 (cr=6870 pr=0 pw=0 time=7670 us)
1721227 TABLE ACCESS FULL ORDERS_SETTLMENT_TBS PARTITION: 3 3 (cr=6870 pr=0 pw=0 time=7646 us)
312 BUFFER SORT (cr=0 pr=0 pw=0 time=208 us)
12 VIEW (cr=0 pr=0 pw=0 time=72 us)
12 UNION-ALL (cr=0 pr=0 pw=0 time=54 us)
1 FAST DUAL (cr=0 pr=0 pw=0 time=3 us)
1 FAST DUAL (cr=0 pr=0 pw=0 time=2 us)
1 FAST DUAL (cr=0 pr=0 pw=0 time=0 us)
1 FAST DUAL (cr=0 pr=0 pw=0 time=0 us)
1 FAST DUAL (cr=0 pr=0 pw=0 time=0 us)
1 FAST DUAL (cr=0 pr=0 pw=0 time=0 us)
1 FAST DUAL (cr=0 pr=0 pw=0 time=2 us)
1 FAST DUAL (cr=0 pr=0 pw=0 time=1 us)
1 FAST DUAL (cr=0 pr=0 pw=0 time=1 us)
1 FAST DUAL (cr=0 pr=0 pw=0 time=0 us)
1 FAST DUAL (cr=0 pr=0 pw=0 time=0 us)
1 FAST DUAL (cr=0 pr=0 pw=0 time=1 us)
136 VIEW (cr=40325 pr=33215 pw=0 time=101,678,318 us)
136 SORT GROUP BY (cr=40325 pr=33215 pw=0 time=101,678,162 us)
19827 HASH JOIN (cr=40325 pr=33215 pw=0 time=101,446,253 us)
45426 PARTITION RANGE SINGLE PARTITION: 10 10 (cr=33455 pr=33215 pw=0 time=98,542,613 us)
45426 TABLE ACCESS FULL ORDERS_MANAGMENTS PARTITION: 10 10 (cr=33455 pr=33215 pw=0 time=98,542,597 us)
1721227 PARTITION RANGE SINGLE PARTITION: 3 3 (cr=6870 pr=0 pw=0 time=1,729,734 us)
1721227 TABLE ACCESS FULL ORDERS_SETTLMENT_TBS PARTITION: 3 3 (cr=6870 pr=0 pw=0 time=8491 us)
L’information ”row source operation” représente le vrai plan d’exécution suivi par Oracle lors de l’exécution de la requête. Je vais diviser ce plan (diviser pour régner) en deux parties distinctes :
Partie 1
312 VIEW (cr=40325 pr=33215 pw=0 time=114,999,408 us)
312 MERGE JOIN CARTESIAN (cr=40325 pr=33215 pw=0 time=114,999,403 us)
26 VIEW (cr=40325 pr=33215 pw=0 time=114,998,980 us)
26 HASH GROUP BY (cr=40325 pr=33215 pw=0 time=114,998,974 us)
19827 HASH JOIN SEMI (cr=40325 pr=33215 pw=0 time=114,911,666 us)
45426 PARTITION RANGE SINGLE PARTITION: 10 10 (cr=33455 pr=33215 pw=0 time=112,077,047 us)
45426 TABLE ACCESS FULL ORDERS_MANAGMENTS PARTITION: 10 10 (cr=33455 pr=33215 pw=0 time=112,031,597 us)
1721227 PARTITION RANGE SINGLE PARTITION: 3 3 (cr=6870 pr=0 pw=0 time=7670 us)
1721227 TABLE ACCESS FULL ORDERS_SETTLMENT_TBS PARTITION: 3 3 (cr=6870 pr=0 pw=0 time=7646 us)
312 BUFFER SORT (cr=0 pr=0 pw=0 time=208 us)
12 VIEW (cr=0 pr=0 pw=0 time=72 us)
12 UNION-ALL (cr=0 pr=0 pw=0 time=54 us)
1 FAST DUAL (cr=0 pr=0 pw=0 time=3 us)
1 FAST DUAL (cr=0 pr=0 pw=0 time=2 us)
1 FAST DUAL (cr=0 pr=0 pw=0 time=0 us)
1 FAST DUAL (cr=0 pr=0 pw=0 time=0 us)
1 FAST DUAL (cr=0 pr=0 pw=0 time=0 us)
1 FAST DUAL (cr=0 pr=0 pw=0 time=0 us)
1 FAST DUAL (cr=0 pr=0 pw=0 time=2 us)
1 FAST DUAL (cr=0 pr=0 pw=0 time=1 us)
1 FAST DUAL (cr=0 pr=0 pw=0 time=1 us)
1 FAST DUAL (cr=0 pr=0 pw=0 time=0 us)
1 FAST DUAL (cr=0 pr=0 pw=0 time=0 us)
1 FAST DUAL (cr=0 pr=0 pw=0 time=1 us)
Partie 2
136 VIEW (cr=40325 pr=33215 pw=0 time=101,678,318 us)
136 SORT GROUP BY (cr=40325 pr=33215 pw=0 time=101,678,162 us)
19827 HASH JOIN (cr=40325 pr=33215 pw=0 time=101,446,253 us)
45426 PARTITION RANGE SINGLE PARTITION: 10 10 (cr=33455 pr=33215 pw=0 time=98,542,613 us)
45426 TABLE ACCESS FULL ORDERS_MANAGMENTS PARTITION: 10 10 (cr=33455 pr=33215 pw=0 time=98,542,597 us)
1721227 PARTITION RANGE SINGLE PARTITION: 3 3 (cr=6870 pr=0 pw=0 time=1,729,734 us)
1721227 TABLE ACCESS FULL ORDERS_SETTLMENT_TBS PARTITION: 3 3 (cr=6870 pr=0 pw=0 time=8491 us)
Les deux parties sont passées en jointure du type ”HASH” via la première opération
Rows Row Source Operation
------- ---------------------------------------------------
312 HASH JOIN OUTER (cr=80650 pr=66430 pw=0 time=216,681,765 us)
Générant 312 lignes en 216 seconds. Multipliez ceci par 2 exécutions et vous allez retrouver l’image exacte rapportée par le résumé du fichier TKRPOF ; c’est-à-dire 624 lignes en 420 secondes.
call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 2 0.02 0.02 0 0 0 0 Execute 2 0.00 0.00 0 0 0 0 Fetch 44 34.35 420.94 132860 161300 0 624 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 48 34.37 420.96 132860 161300 0 624
En observant attentivement les deux parties, on peut très facilement constater que les opérations les plus gourmandes en temps de réponse sont respectivement :
Rows Row Source Operation ------- ------------------------------------------------------------------------------------------------------ 45426 TABLE ACCESS FULL ORDERS_MANAGMENTS PARTITION: 10 10 (cr=33455 pr=33215 pw=0 time=112,031,597 us) 45426 TABLE ACCESS FULL ORDERS_MANAGMENTS PARTITION: 10 10 (cr=33455 pr=33215 pw=0 time=98,542,597 us)
Qui consomment 112 et 98 secondes chacune respectivement.
Ces deux opérations à elles seules nécessitent 200 seconds alors que le temps total consommé par l’entièreté des opérations contenues dans le plan d’exécution est de 216 secondes environ. Il est donc plus qu’évident que revoir les deux accès à ces deux tables peut conduire à un meilleur temps d’exécution.
Vous avez peut-être déjà constaté l’opération MERGE JOIN CARTESIAN faite sur une table directrice générant 26 lignes. Je reviendrai à cette situation plus tard dans un autre article.
Que pouvons-nous encore interpréter ? Avons-nous atteint le point où le contenu de la requête devient essentiel ?
Pas vraiment. Mais nous sommes très proches de la limite de cette nécessité.
En observant le nombre de lignes générées par l’opération TABLE ACCESS FULL (45426) une question s’est imposée d’elle-même : combien de lignes contient cette table ?
select count(*) from ORDERS_MANAGMENTS ----> 8,999,341
Remarquez l’évidence : cette opération produit 45,426 lignes à partir d’une table contenant 8,999,341 lignes en utilisant un FULL TABLE SCAN pour cela ; 0,005% de lignes via un FULL TABLE SCAN !. Quelque chose est à revoir ici.
A partir de là, nous ne pouvons pas aller plus loin dans nos investigations sans analyser le contenu de la requête, le type de tables, les indexes qui lui sont liés, les différentes where clauses appliquées, etc…
Ceci sera traité dans le prochain article.
Mohamed Houri’s Oracle Notes 
très bon article. Merci
Comment by zikoracle — December 3, 2012 @ 3:22 pm |
Bravo la suite svp 🙂 et surtout une analyse du rapport AWR dans le même style ! merci
Comment by Bravo la suite svp :) et surtout une analyse du rapport AWR dans le même style ! merci — December 3, 2012 @ 9:29 pm |
Salut Mohamed,
je découvre ton blog.
Bravo c’est très bien écrit et bien emmené.
Bonne continuation
Comment by ahmed aangour — March 8, 2013 @ 2:03 pm |
Très cher Ahmed,
Merci pour tes encouragements.
Comment by hourim — March 9, 2013 @ 8:41 pm |
L’interprétation de colonne “query” est fausse. Cela ne correspond pas au bloc lus en mémoire, mais ceux nécessaires pour une lecture consistente. Cela peut nécessité de la lecture de blocs physiques. Revoyez la doc Oracle.
Cordialement.
Carlos
Comment by Carlos — October 24, 2014 @ 11:55 am |
Merci pour votre commentaire qui aurait été complet s’il eut été accompagné de ladite doc Oracle.
D’abord dites-moi ce que vous avez compris par ’’bloc lus en mémoire’’. Peut-être vous êtes assez précis en français et vous auriez aimé que j’écrive ’’bloc lus à partir de la mémoire’’. Si tant est que cela est vrai, alors à partir d’où est faite une lecture consistante (read consistency) d’un bloc selon vous? Si je vous ai bien compris vous proclamez qu’une lecture consistante peut se faire à partir d’une lecture physique ?
Comment est-ce possible qu’une lecture consistante (read consistent gets) puisse se faire à partir du disque ? Une reconstruction d’une image d’un bloc de données contenu dans la mémoire (buffer cache) que vous n’êtes pas autorisé à voir, se fait toujours à partir du buffer cache (appelé aussi cache du data ou mémoire où sont stockées les blocs suite à une lecture logique) en utilisant les undo records et dans ce cas cela s’appelle un consistent read (cr dans le row source plan du TKPROF). Et cela est accompagné par 3 events qui sont:
CR blocks created
Data blocks consistent reads – undo records applied
Consistent gets – examination
Donc, le mot QUERY du TKPROF compte:
Le nombre de blocs reconstruitsmais aussi
Le nombre de blocs visités dans les undo blocks pour accomplir cette reconstruction
Ceci est confirmé dans le livre de Tom Kyte (Expert Oracle) où il a définit ceci:
QUERY – How many blocks we processed in consistent-read mode. This will include counts of
blocks read from the rollback segment in order to ‘rollback’ a block.
Par abus de langage, n’ai-je pas le droit de dire que par QUERY, j’entends le nombre de blocs (buffer) lu à partir de la mémoire(buffer cache) ?
Voici les étapes qu’Oracle suit pour reconstruire une image consistante avec le SCN du début de votre requête
Lorsqu’Oracle arrive au bloc de données à retourner pour le client et se rend compte qu’il doit reconstruire une image consistante il
1. fait une copie de ce block de données dans le buffer cache (dans la mémoire)
2. Prend l’undo correspondant à partir de l’undo tablespace —> ** (voir explication ci-dessous)
3. Applique cet undo (dans le buffer cache et donc dans la mémoire) à cette copie pour retrouver l’image qui correspond au SCN de la requête en question
4. Renvoi enfin cette image consistante au client
Une autre session voulant reconstruire une image consistante du même bloc peut :
1. Soit refaire les 4 opérations ci-dessus dans le cas où l’image obtenue à l’étape 4 a été sortie du buffer cache
2. Soit renvoyer la même image obtenue lors de l’opération 4 si celle-ci se trouve encore dans le buffer cache.
3. Soit utiliser la copie du block obtenue lors de l’opération 1 (si celle-ci se trouve encore dans le buffer cache) et lui appliquer l’undo correspondant à son propre SCN (car la copie 4 peut correspondre à une session dotée d’un SCN différent) pour en renvoyer une nouvelle image consistante
Et enfin voici un exemple où (Buffers=consistent gets = QUERY = 3)
drop table t1; create table t1 as select rownum id1, trunc(dbms_random.value(1,1000)) id2, lpad(rownum,10,'0') small_vc, rpad('x',1000) padding from dual connect by level <= 1e4; alter table t1 add constraint t1_pk primary key (id1); create index t1_i1 on t1(id2); SELECT count(t1.small_vc) FROM t1 WHERE t1.id1 = 42 ; SQL> alter system set statistics_level=all; System altered. SQL> SELECT 2 count(t1.small_vc) 3 FROM 4 t1 5 WHERE 6 t1.id1 = 42 7 ; COUNT(T1.SMALL_VC) ------------------ 1 SQL> start xstat ------------------------------------------------------------------------------------------------ | Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | ------------------------------------------------------------------------------------------------ | 0 | SELECT STATEMENT | | 1 | | 1 |00:00:00.01 | 3 | | 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:00.01 | 3 | | 2 | TABLE ACCESS BY INDEX ROWID| T1 | 1 | 1 | 1 |00:00:00.01 | 3 | |* 3 | INDEX UNIQUE SCAN | T1_PK | 1 | 1 | 1 |00:00:00.01 | 2 | ------------------------------------------------------------------------------------------------ Predicate Information (identified by operation id): --------------------------------------------------- 3 - access("T1"."ID1"=42) SQL> SELECT 2 count(t1.small_vc) 3 FROM 4 t1 5 WHERE 6 t1.id1 = 42 7 ; COUNT(T1.SMALL_VC) ------------------ 1 Statistics ---------------------------------------------------------- 0 recursive calls 0 db block gets 3 consistent gets 0 physical reads 0 redo size 552 bytes sent via SQL*Net to client 544 bytes received via SQL*Net from client 2 SQL*Net roundtrips to/from client 0 sorts (memory) 0 sorts (disk) 1 rows processedEt le TKPROF correspondant
SELECT count(t1.small_vc) FROM t1 WHERE t1.id1 = 42 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 1 0.00 0.00 0 0 0 0 Fetch 2 0.00 0.00 0 3 0 1 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 4 0.00 0.00 0 3 0 1 Misses in library cache during parse: 0 Optimizer mode: ALL_ROWS Parsing user id: 102 Number of plan statistics captured: 1 Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 1 1 1 SORT AGGREGATE (cr=3 pr=0 pw=0 time=88 us) 1 1 1 TABLE ACCESS BY INDEX ROWID T1 (cr=3 pr=0 pw=0 time=64 us cost=2 size=15 card=1) 1 1 1 INDEX UNIQUE SCAN T1_PK (cr=2 pr=0 pw=0 time=42 us cost=1 size=0 card=1)(object id 95556)*** Le block initialement lu contient une entrée ITL (Interested Transaction List) qui pointe sur une information appelée ‘’undo record address’’. Cette adresse contient le numéro du fichier, le numéro du block et le numéro de l’enregistrement dans le bloc undo. Grâce à ces informations contenues dans le bloc de données nécessitant une lecture consistante, Oracle va directement au bon undo bock pour rechercher les instructions (update/insert/delete) à appliquer à la copie du block dans le buffer cache.
Bien à vous
Comment by hourim — October 27, 2014 @ 1:46 pm |
Il se peut que lors de la reconstruction d’un bloc pour une lecture consistante, le undo bloc nécessaire à cette reconstruction contenu dans un redo log vector (avec le redo log correspondant), ait été “flaché” dans le disque via le LGWR (pour une raison ou une autre). Dans ce cas, Oracle va faire (a) une lecture physique via db file sequential read pour lire le undo bloc correpondant du disque(à partir de l’undo tablespace) vers le buffer cache (b) faire une copie du bloc de donnée trouvé dans le buffer cache (a) appliquer les undos lus physiquement sur la copie du bloc de données et renvoyer alors l’image consistante.
Parfois, pour une très longue transaction, il se peut aussi que le bloc à lire d’une manière consistante ait été lui aussi flashé dans le disque et auquel cas une lecture physique s’impose pour le remettre dans le buffer cache afin de lui appliquer l’undo correspondant.
Mais même dans ce cas, sachez que toute lecture physique est forcément précédée par une lecture logique. C’est pour cette raison que (sauf dans le cas de table prefetch et autres) le nombre de lectures logiques est toujours supérieur au nombre de lectures physiques
Comment by hourim — October 27, 2014 @ 8:00 pm |
Bonjour mohamed
Consistent read très bien expliquée: correspond exactement a celle donnée par Craig shallahamer dans son livre Oracle Performance Firefighting
Bonne continuation
Comment by Mohamed seghir souidi — January 19, 2015 @ 11:21 pm |
http://www.comeonyoga.cn/home.php?mod=space&uid=16674&do=profile&from=space
Interprétation d’un fichier TKPROF | Mohamed Houri’s Oracle Notes
Trackback by http://www.comeonyoga.cn/home.php?mod=space&uid=16674&do=profile&from=space — December 6, 2019 @ 6:53 pm |
Positive Thinking
Interprétation d’un fichier TKPROF | Mohamed Houri’s Oracle Notes
Trackback by Positive Thinking — September 20, 2020 @ 8:01 am |