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.
0.000000
0.000000
Mohamed Houri’s Oracle Notes 