Mohamed Houri’s Oracle Notes

December 31, 2012

2012 in review

Filed under: Oracle — hourim @ 7:04 pm

Finally, 2012 came to its end. Unsurprisingly my blog has not been as active as I wished it to be.

My busiest day was September the 18th in which I have published an article about interpreting TKRPOF which turned to be the most active article in my blog. This gave me a clear indication on what subject my readers want to see me focusing on. Mostly, articles that deals about explaining Oracle features using an elegant and an attractive way of narrating the core concept of those features as I did for the TKPROF article. I will keep myself on that way. In the meantime I wanted to share with you, below, my 2012 annual blog report.

Thanks to all of you and happy New Year.

Click here to see the complete report.

December 3, 2012

Interprétation d’un fichier TKPROF

Filed under: French-Translation — hourim @ 11:08 am

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.

Create a free website or blog at WordPress.com.

Tony's Oracle Tips

Tony Hasler's light hearted approach to learning about Oracle

Richard Foote's Oracle Blog

Focusing Specifically On Oracle Indexes, Database Administration and Some Great Music

Hatem Mahmoud Oracle's blog

Just another Oracle blog : Database topics and techniques

Mohamed Houri’s Oracle Notes

Qui se conçoit bien s’énonce clairement

Oracle Diagnostician

Performance troubleshooting as exact science

Raheel's Blog

Things I have learnt as Oracle DBA

Coskan's Approach to Oracle

What I learned about Oracle

So Many Oracle Manuals, So Little Time

“Books to the ceiling, Books to the sky, My pile of books is a mile high. How I love them! How I need them! I'll have a long beard by the time I read them”—Lobel, Arnold. Whiskers and Rhymes. William Morrow & Co, 1988.

EU Careers info

Your career in the European Union

Carlos Sierra's Tools and Tips

Tools and Tips for Oracle Performance and SQL Tuning

Oracle Scratchpad

Just another Oracle weblog

OraStory

Dominic Brooks on Oracle Performance, Tuning, Data Quality & Sensible Design ... (Now with added Sets Appeal)