Problème de performance lié à la désactivation du Bind Peeking (_OPTIM_PEEK_USER_BINDS)

J'ai été sollicité la semaine dernière par un développeur pour intervenir sur un problème de performance lié à la requête suivante:

SELECT  MAX(QRT_BENCH_DATE) PREVIOUS_DATE
FROM admlxa.MUT_EXCHANGE_NORM_LINK, admlxa.QRT_BENCH, admlxa.QRT_COMMON_PARAMS_ID_LNS 
WHERE ENL_EXCHANGE_NORM_ID IN (50002, 50003)
AND QRT_BENCH_ELIOT_ID = ENL_NORM_CODE
AND QRT_BENCH_NAME LIKE LNS_PORTFOLIO_TRANSCOI9QM || '%'
AND LNS_PORTFOLIO_TRANSCOI9QM IS NOT NULL
AND NOT QRT_BENCH_NAME LIKE '%TESTARVAL'
AND QRT_BENCH_PREMIUM <> 0
AND ENL_OBJECT_ID = :a1
AND LNS_ID_EUR = :a2
AND QRT_BENCH_DATE < :a3 ;

Cette requête était exécutée plusieurs fois dans une boucle et mettait à chaque fois plus de 2 minutes pour s'exécuter. Le plan d'exécution choisi par le CBO est le suivant:

-----------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                        | Name                        | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |
-----------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                 |                             |      1 |        |      1 |00:02:13.08 |     285K|    260K|
|   1 |  SORT AGGREGATE                  |                             |      1 |      1 |      1 |00:02:13.08 |     285K|    260K|
|*  2 |   TABLE ACCESS BY INDEX ROWID    | QRT_BENCH                   |      1 |      2 |      0 |00:02:13.08 |     285K|    260K|
|   3 |    NESTED LOOPS                  |                             |      1 |      1 |   8048K|00:00:34.38 |   28503 |  28515 |
|   4 |     MERGE JOIN CARTESIAN         |                             |      1 |      1 |      1 |00:00:00.05 |      40 |     38 |
|*  5 |      TABLE ACCESS FULL           | MUT_EXCHANGE_NORM_LINK      |      1 |      1 |      1 |00:00:00.04 |      38 |     37 |
|   6 |      BUFFER SORT                 |                             |      1 |      1 |      1 |00:00:00.01 |       2 |      1 |
|*  7 |       TABLE ACCESS BY INDEX ROWID| QRT_COMMON_PARAMS_ID_LNS    |      1 |      1 |      1 |00:00:00.01 |       2 |      1 |
|*  8 |        INDEX RANGE SCAN          | PK_QRT_COMMON_PARAMS_ID_LNS |      1 |      1 |      1 |00:00:00.01 |       1 |      1 |
|*  9 |     INDEX RANGE SCAN             | IDX_QRT_BENCH_1             |      1 |  78876 |   8048K|00:00:20.25 |   28463 |  28477 |
-----------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - filter(("QRT_BENCH_ELIOT_ID" IS NOT NULL AND "QRT_BENCH_NAME" NOT LIKE '%TESTARVAL' AND "QRT_BENCH_PREMIUM"<>0 AND
              "QRT_BENCH_NAME" IS NOT NULL AND "QRT_BENCH_ELIOT_ID"="ENL_NORM_CODE" AND "QRT_BENCH_NAME" LIKE
              "LNS_PORTFOLIO_TRANSCOI9QM"||'%'))
   5 - filter(("ENL_OBJECT_ID"=:A1 AND INTERNAL_FUNCTION("ENL_EXCHANGE_NORM_ID")))
   7 - filter("LNS_PORTFOLIO_TRANSCOI9QM" IS NOT NULL)
   8 - access("LNS_ID_EUR"=:A2)
   9 - access("QRT_BENCH_DATE"<:A3)

Le plan ci-dessus a été généré avec les stats d'exécution (paramètre STATISTICS_LEVEL=ALL au niveau de la session). On voit que la requête met plus de 2 minutes à s'exécuter(colonne A-TIME) et que l'essentiel du temps d'exécution concerne la récupération des lignes dans la table QRT_BENCH à partir des ROWIDs de l'index IDX_QRT_BENCH_1. Le problème ici est que l'optimiseur a décidé d'utiliser un accès indexé pour récupérer plus de 8 millions de lignes dans la table QRT_BENCH (soit la quasi totalité de la table). On devine la cause de l'erreur en comparant les colonnes E-ROWS et A-ROWS pour l'opération 9 du plan (INDEX RANGE SCAN). La colonne E-ROWS indique le nombre de lignes estimées par l'optimiseur pendant la phase de parsing de la requête alors que la colonne A-ROWS indique le nombre de lignes réellement traitées pendant l'exécution de la requête. On constate ici que l'optimiseur a estimé que le parcours de l'index retournerait 78 876 lignes alors que le nombre réel est de 8 048 000. Pourquoi l'optimiseur se trompe t-il à ce point? En regardant la trace 10053 j'ai pu m'apercevoir que le paramètre caché _OPTIM_PEEK_USER_BINDS avait été (pour des raisons encore obscures) désactivé sur cette base . Ce paramètre à FALSE indique simplement que la fonctionnalité du BIND VARIABLE PEEKING permettant à l'optimiseur de connaitre la valeur des variables bindées au moment de la phase de hard parse est désactivé. (Pour plus d'informations sur le BIND VARIABLE PEEKING vous pouvez voir ici mon poste précédent sur ce sujet). Si le Bind Peeking est désactivé le CBO utilise alors un pourcentage fixe de la table comme estimation de la cardinalité retournée. Ce que j'ai appris comme tout le monde dans le livre de Jonathan Lewis c'est que pour les clauses de type "<" ou ">" une sélectivité de 5% est utlisée par le CBO. Or ici 8763975*0.05 = 438198. Dans le plan on a une cardinalité de 78876. NOTE: le nombre 8763975 correspond à la colonne NUM_ROWS dans USER_INDEXES pour l'index IDX_QRT_BENCH_1. Voici le plan qu'on obtient pour une requête n'impliquant que la table QRT_BENCH:

SQL> explain plan for select * from  admlxa.QRT_BENCH where QRT_BENCH_DATE < :a3;
 Explained.

 Elapsed: 00:00:00.01

 SQL> select * from table(dbms_xplan.display);
 PLAN_TABLE_OUTPUT
 -----------------
 Plan hash value: 2896103184

 -----------------------------------------------------------------------------------------------
 | Id  | Operation                   | Name            | Rows  | Bytes | Cost> (%CPU)| Time     |
 -----------------------------------------------------------------------------------------------
 |   0 | SELECT STATEMENT            |                 |   424K|    81M| 3170 (4)| 00:00:05 |
 |   1 |  TABLE ACCESS BY INDEX ROWID| QRT_BENCH       |   424K|    81M| 3170> (4)| 00:00:05 |
 |*  2 |   INDEX RANGE SCAN          | IDX_QRT_BENCH_1 | 78876 |       | 303> (5)| 00:00:01 |
 -----------------------------------------------------------------------------------------------

 Predicate Information (identified by operation id):
 ---------------------------------------------------
   2 - access("QRT_BENCH_DATE"<:A3)

La cardinalité de l'opération 1 (accès aux données de la table) est de 424K ce qui correspond bien à une sélectivité de 5%: 8480798*0.05 = 424039 NOTE: le nombre 8480798 correspond à la colonne NUM_ROWS dans USER_TAB_STATISTICS pour la table QRT_BENCH. Par contre pour l'INDEX RANGE SCAN on retrouve nos 78 876. Alors d'où vient ce nombre? Après avoir reparcouru en vain le livre de Jonathan LEWIS j'ai décidé de lui envoyer un email directement pour connaitre quelle sélectivité le CBO utilisait pour les INDEX RANGE SCAN. A peine le mail parti que mon collègue avait déjà mis le doigt sur la réponse sur le site de Jonathan : http://www.jlcomp.demon.co.uk/cbo_book/ch_04.html#_Index_Selectivity_(14th_Dec_2005) On peut y lire que pour la sélectivité des index (pour les clauses "<" ou ">") le pourcentage appliqué est de 0.9%. Jonathan LEWIS avec sa grande gentillesse et l'humilité qui le caractérise m'a quand même répondu. Le plus drôle dans l'histoire c'est qu'il avait oublié qu'il connaissait la réponse. Il a d'ailleurs écrit un article le soir même sur son blog sur ce sujet: http://jonathanlewis.wordpress.com/2011/02/10/cboddity/ Pour en revenir à notre problème initial la solution consiste donc à réactiver le BIND VARIABLE PEEKING via le paramètre caché:

alter session set "_optim_peek_user_binds"=TRUE;

Le plan qu'on obtient désormais indique une bonne cardinalité pour la table QRT_BENCH et on voit que l'INDEX RANGE SCAN a laissé place à un Full Table Scan plus approprié.

----------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                       | Name                        | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |
----------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                |                             |      1 |        |      1 |00:00:17.91 |     246K|    197K|
|   1 |  SORT AGGREGATE                 |                             |      1 |      1 |      1 |00:00:17.91 |     246K|    197K|
|*  2 |   HASH JOIN                     |                             |      1 |     22 |      0 |00:00:17.91 |     246K|    197K|
|   3 |    MERGE JOIN CARTESIAN         |                             |      1 |      1 |      1 |00:00:00.04 |      40 |     35 |
|*  4 |     TABLE ACCESS FULL           | MUT_EXCHANGE_NORM_LINK      |      1 |      1 |      1 |00:00:00.03 |      38 |     34 |
|   5 |     BUFFER SORT                 |                             |      1 |      1 |      1 |00:00:00.01 |       2 |      1 |
|*  6 |      TABLE ACCESS BY INDEX ROWID| QRT_COMMON_PARAMS_ID_LNS    |      1 |      1 |      1 |00:00:00.01 |       2 |      1 |
|*  7 |       INDEX RANGE SCAN          | PK_QRT_COMMON_PARAMS_ID_LNS |      1 |      1 |      1 |00:00:00.01 |       1 |      1 |
|*  8 |    TABLE ACCESS FULL            | QRT_BENCH                   |      1 |   4136K|    645K|00:00:17.20 |     246K|    197K|
----------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("QRT_BENCH_ELIOT_ID"="ENL_NORM_CODE")
       filter("QRT_BENCH_NAME" LIKE "LNS_PORTFOLIO_TRANSCOI9QM"||'%')
   4 - filter(("ENL_OBJECT_ID"=:A1 AND INTERNAL_FUNCTION("ENL_EXCHANGE_NORM_ID")))
   6 - filter("LNS_PORTFOLIO_TRANSCOI9QM" IS NOT NULL)
   7 - access("LNS_ID_EUR"=:A2)
   8 - filter(("QRT_BENCH_ELIOT_ID" IS NOT NULL AND "QRT_BENCH_NAME" NOT LIKE '%TESTARVAL' AND "QRT_BENCH_DATE"<:A3 AND
              "QRT_BENCH_PREMIUM"<>0 AND "QRT_BENCH_NAME" IS NOT NULL))

Bien sûr la requête peut être encore améliorée notamment en travaillant sur les clauses de jointure avec la table QRT_BENCH mais au moins avec le BIND PEEKING, le CBO arrive à estimer de bonnes cardinalités.

Remonter dans le temps avec Flashback Query

La dernière application sur laquelle j'ai travaillé contenait des requêtes basées sur des tables de travail, c'est à dire des tables remplies en début de traitement et supprimées à la fin. Lorsque je devais traiter un problème de performance sur une des requêtes impliquant une ou plusieurs de ces tables je me heurtais au fait que je ne pouvais pas reproduire le problème de performance car ces tables ne contenaient plus les données processées au moment de l'exécution.

Heureusement le Flashback Query m'est venu plusieurs fois en aide.
Le principe du FlashBack Query consiste à requêter une table via une clause SELECT + une clause "AS OF" permettant de préciser à quelle date (Time Stamp) ou à quel Numero SCN on souhaiterait voir l’image de la table.
Imaginons par exemple que mon traitement batch s’exécute entre 4h et 6h du matin et qu’à 9H lors de mon arrivée au boulot (bon ok 10h pour ceux qui me connaissent), je dois analyser pourquoi une requête a mis 30 minutes pour s’exécuter au lieu de 2 minutes. L’idéal serait de pouvoir reproduire le problème de performance sur cette requête mais si les données de ma table de travail ont été supprimées à la fin de mon batch, c’est impossible. L’idée d'utiliser le Flashback Query ici est de pouvoir réinsérer dans cette table les données qu’elle contenait à 4 heures du matin. Selon la taille du tablespace Undo et/ou selon la valeur du paramètre UNDO_RETENTION, il y’a de fortes chances que je puisse récupérer les lignes grâce à la requête suivante :

select * from TABLE_TRAVAIL AS OF TIMESTAMP TO_TIMESTAMP('2011-01-31 04:00:00', 'YYYY-MM-DD HH24:MI:SS');

Exemple:

Comme le PSG a gagné ce week-end je vais me crée une table PSG contenant le numéro, nom et prénom de certains joueurs qui ont fait la gloire de mon club (tiens je viens de perdre des lecteurs marseillais):

SQL> create table PSG (num number, nom varchar2(20), prenom varchar2(20));

Table créée.

SQL> insert into PSG values(1,'LAMA','Bernard');

1 ligne créée.

SQL> insert into PSG values(10,'OKOCHA','Jay-Jay');

1 ligne créée.

SQL> insert into PSG values(9,'PAULETA','Pedro Miguel');

1 ligne créée.

SQL> insert into PSG values(11,'GINOLA','David');

1 ligne créée.

SQL> commit;

Validation effectuée.

SQL> select * from psg;

       NUM NOM                  PRENOM
---------- -------------------- --------------------
         1 LAMA                 Bernard
        10 OKOCHA               Jay-Jay
         9 PAULETA              Pedro Miguel
        11 GINOLA               David

La table contient 4 lignes.
Je vais maintenant supprimer toutes les lignes de ma table et biens sûr commiter:

SQL> delete psg;

4 ligne(s) supprimée(s).

SQL> commit;

Validation effectuée.

Voilà que j'ai perdu toutes mes lignes :-(

SQL> select * from PSG;

aucune ligne sélectionnée

Grâce au Flashback Query je peux voir les données que contenait cette table avant le DELETE.
La table ayant été supprimé il y'a quelques minutes je peux requêter la table en faisant un SYSTIMESTAMP - 10 minutes:

SQL> select * from PSG AS OF TIMESTAMP ( systimestamp - 10/1440);

       NUM NOM                  PRENOM
---------- -------------------- --------------------
         1 LAMA                 Bernard
        10 OKOCHA               Jay-Jay
         9 PAULETA              Pedro Miguel
        11 GINOLA               David

Comme par magie j'ai pu retrouver l'image de ma table telle qu'elle était à un moment dans le passé.

Si j'avais voulu requêter la table en précisant une heure précise j'aurais exécuté la requête suivante:

SQL>   select * from PSG AS OF TIMESTAMP TO_TIMESTAMP ('2011-01-31 15:45:00', 'YYYY-MM-DD HH24:MI:SS');

       NUM NOM                  PRENOM
---------- -------------------- --------------------
         1 LAMA                 Bernard
        10 OKOCHA               Jay-Jay
         9 PAULETA              Pedro Miguel
        11 GINOLA               David

CONCLUSION:
En plus d'épater la galerie le Flashback Query peut vraiment vous être d'une grande aide lors d'un DELETE accidentel ou bien lorsque vous vous voulez analyser un problème de requête en PROD sur des données volatiles.
Pour augmenter les chances de conserver vos données du passé vous pouvez augmenter la taille du tablespace UNDO et augmenter la valeur du paramètre UNDO_RETENTION. Ce dernier permet d'augmenter la durée de rétention des données commitées dans le tablespace UNDO.

Introduction au parallélisme d’Oracle

Cet article est une introduction à une série d’article à venir sur le parallélisme d’Oracle.

Principe :

Par défaut lorsque vous exécutez une requête celle-ci s’exécute de manière séquentielle c’est à dire que vous n’avez qu’un seul process server qui travaille pour vous. Donc même si vous avez plusieurs CPU, le process server ne pourra en utiliser qu’un seul.

Le but du parallélisme dans une base Oracle est de répartir sur plusieurs process esclaves ("slave process") une tâche adressée initialement à un process server. La coordination de ces process est géré par le process server lui-même qu’on appelle dans ce cas le « Query Coordinator » L’avantage c’est que chacun de ces process esclaves pourra utiliser un CPU différent. On profite ainsi pleinement des ressources disponibles sur le serveur (CPU, RAM, I/O).

Un parallélisme approprié peut faire passer une requête de plusieurs heures à quelques minutes seulement, mais attention, un parallélisme inappropriée peut avoir l’effet inverse.

Analogie :

Le parallélisme utilisé par Oracle ressemble à ce que tout le monde fait dans la vie de tous les jours. Imaginons que vous souhaitez rénover votre appartement. Si vous êtes tout seul à travailler vous devrez repeindre chacune de vos pièces les unes après les autres. Vous travaillerez alors en mode séquentiel. Par contre si vous êtes 4 amis à travailler vous pouvez vous partager les tâches. Chacun par exemple pourra s’occuper de repeindre une pièce. Vous travaillerez donc en mode parallèle. Vous perdrez juste un peu de temps pour vous coordonner mais au final vous serez plus efficaces.

Maintenant imaginons que vous n’ayez qu’un mur à repeindre. Vous perdrez plus de temps en vous mettant à plusieurs qu’en le faisant tout seul (je suis en plein chantier peinture en ce moment chez moi c'est pour ça que cet exemple m'est venu à l'esprit).

Le parallélisme d’Oracle fonctionne selon le même principe. Si vous avez de grosses requêtes qui mettent du temps à s’exécuter et dont les opérations sont facilement divisibles en sous-tâches (ex : parcours de plusieurs partitions d’une table) alors vous y gagneriez en parallélisant. Par contre si vous décidez de paralléliser un select retournant qu’une ligne via un index unique alors votre requête sera moins performante car la gestion des process « slaves » sera plus coûteuse que l’exécution de la requête elle-même.

Quand utiliser le parallélisme :

Le parallélisme est approprié lorsque :
- Vous avez plusieurs CPU disponibles
- Les données sont réparties sur plusieurs disques (stripping)
- L’instruction SQL met du temps à s’exécuter car consomme beaucoup de ressources (ex : Full Table Scan sur une grosse table avec une clause ORDER BY).
- Votre requête ne s’exécute pas dans un environnement hyper concurrentiel (base OLTP)

Le parallélisme peut être utilisé en générale dans les instructions suivantes:
- Un select massif effectuant de l’accès multiblocks (Full Table Scan ou Fast Full Index Scan). On parle de « Parallel Query ».
- Un update/delete/insert massif. On parle de « Parallel DML ».
- Pour les rebuilds d’index ou les CTAS (Create Table As Select). On parle de « Parallel DDL ».


Degrée de parallélisme (DOP) :

Le degré de parallélisme correspond au nombre de process esclaves utilisé pour une instruction en mode parallèle.
Par exemple la commande ci-dessous crée une table TOTO en mode parallèle avec un DOP de 8. Cela veut dire que 8 process « slaves » (donc 8 CPU) seront utilisées pour les requêtes effectuées sur cette table :

CREATE TABLE TOTO (c1 NUMBER, c2 VARCHAR2(100)) PARALLEL 8 ;

Vous pouvez vérifier qu’une table est définie en mode parallèle ou pas en interrogeant la colonne DEGREE de la vue USER_TABLES :

SQL> select table_name,degree from user_tables where table_name='TOTO';

TABLE_NAME                     DEGREE
------------------------------ ----------
TOTO                                    8

Si la clause PARALLEL est utilisée sans spécifier le degré de parallélisme, le DOP utilisée sera alors le résultat de la multiplication suivante :

CPU_COUNT * PARALLEL_THREAD_PER_CPU

CPU_COUNT est le paramètre d’initialisation de la base indiquant le nombre de CPU disponibles et PARALLEL_THREAD_PER_CPU est le paramètre indiquant le nombre de process « slaves » possibles pour un CPU.

Lorsque vous utilisez le parallélisme je recommande de ne pas définir la table en mode parallèle mais plutôt d’utiliser le hint PARALLEL pour les requêtes que vous voulez vraiment paralléliser.

Chaque type d’instructions SQL parallélisable fera l’objet d’un post prochainement :
- Les SELECT en mode parallèle (Parallel Query)
- Les DML en mode parallèle (PDML ou Parallel DML)
- Les DDL en mode parallèle (PDDL ou Parallel DDL)

Trace 10046 et TKPROF

Oracle offre la possibilité de tracer dans un fichier toutes les requêtes SQL et blocs PL/SQL effectués par une session donnée. Cette trace permet de récupérer les informations sur les statistiques d'exécution de ces requêtes: temps d'exécution, temps CPU, temps d'attente, wait events, nombre de lectures logiques, nombre de lectures physiques etc.

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         100

Les 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.00

Aprè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.

Bind Variable Peeking

Un problème rencontré récemment sur une base d'un client m'a rappelé à quel point ce concept était fondamental en matière de tuning SQL.

Comme son nom peut le laisser entendre, le Bind Variable Peeking est lié à l'utilisation des variables bindées pour les requêtes SQL.

Petit rappel sur l'intérêt des binds variables:

Lorsqu'on exécute plusieurs fois une requête pour laquelle seule la valeur littérale d'une colonne est amenée à changer, le CBO doit générer un plan d'exécution pour chacune de ces requêtes. En effet, dans l'exemple ci-dessous comme le corps de chacune des 2 requêtes n'est pas (syntaxiquement) identique, Oracle considère qu'il s'agit d'une nouvelle requête (SQL_ID différent) et va effectuer un HARD PARSE (calcul de plan) pour chacune d'elles :
select * from toto where c1  = 1;
select * from toto where c1  = 2;

SQL> select sql_id,child_number from v$sql where sql_text like 'select * from toto where c1  =%';

SQL_ID        CHILD_NUMBER
------------- ------------
6dchwd6xf9kjq            0
0j5bytr8g767t            0

En utilisant, une variable bindée à la place de la valeur littérale on obtient un partage du curseur. Le plan d'exécution n'est calculé que lors de la première exécution. Les autres fois où la requête est exécutée le plan partagé dans la shared pool sera utilisé (le hard parse est évité):

SQL> variable n number;
SQL> execute :n := 1;
SQL> select * from toto where c1  = :n;
SQL> execute :n := 2;
SQL> select * from toto where c1  = :n;
SQL> select sql_id,child_number,executions from v$sql where sql_text like 'select * from toto where c1  = :n%';

SQL_ID        CHILD_NUMBER EXECUTIONS
------------- ------------ ----------
ffh26jcnjg03y            0          2 

Voyons maintenant en quoi consiste le Bind Peeking:

Dans le schéma SH d'Oracle il existe une table CUSTOMERS dont la colonne COUNTRY_ID (Foreign Key vers la table COUNTRIES) est skewed, c'est à dire que les données pour cette colonne ne sont pas uniformément réparties.

En effet, avec la requête suivante on s'aperçoit que l'essentiel des clients résident aux US alors que les clients les moins nombreux sont en Arabie Saoudite:

SQL> select country_name,cu.country_id,count(1) from customers cu,countries co
  2  where cu.country_id=co.country_id
  3  group by country_name,cu.country_id
  4  order by 3 desc;

COUNTRY_NAME                             COUNTRY_ID   COUNT(1)
---------------------------------------- ---------- ----------
United States of America                      52790      18520
Germany                                       52776       8173
Italy                                         52770       7780
United Kingdom                                52789       7557
France                                        52779       3833
Spain                                         52778       2039
Canada                                        52772       2010
Brazil                                        52775        832
Australia                                     52774        831
China                                         52771        712
Poland                                        52786        708
Japan                                         52782        624
Singapore                                     52769        597
Argentina                                     52773        403
Denmark                                       52777        383
New Zealand                                   52785        244
Turkey                                        52788         91
South Africa                                  52791         88
Saudi Arabia                                  52787         75

Créons un index sur la colonne COUNTRY_ID et collectons les stats sur la table:

SQL> create index idx_cust_country  on customers(country_id);

Index créé

SQL> exec dbms_stats.gather_table_stats(user,'CUSTOMERS',method_opt=>'for all columns size auto',no_invalidate=>FALSE);

Procédure PL/SQL terminée avec succès.

La clause "FOR ALL COLUMNS SIZE AUTO" laisse le choix au CBO de calculer des histogrammes pour les colonnes qu'il juge nécessaires et notamment les colonnes SKEWED.
On peut s'apercevoir grâce à la requête suivante qu'un histogramme a bien été crée pour la colonne COUNTRY_ID:

SQL> select column_name,num_distinct,histogram
  2  from user_tab_col_statistics where table_name='CUSTOMERS';

COLUMN_NAME                    NUM_DISTINCT HISTOGRAM
------------------------------ ------------ ---------------
CUST_ID                               55500 NONE
CUST_FIRST_NAME                        1300 NONE
CUST_LAST_NAME                          908 NONE
CUST_GENDER                               2 NONE
CUST_YEAR_OF_BIRTH                       75 NONE
CUST_MARITAL_STATUS                      11 NONE
CUST_STREET_ADDRESS                   49900 NONE
CUST_POSTAL_CODE                        623 NONE
CUST_CITY                               620 NONE
CUST_CITY_ID                            620 HEIGHT BALANCED
CUST_STATE_PROVINCE                     145 NONE
CUST_STATE_PROVINCE_ID                  145 FREQUENCY
COUNTRY_ID                               19 FREQUENCY
CUST_MAIN_PHONE_NUMBER                51344 NONE
CUST_INCOME_LEVEL                        12 NONE
CUST_CREDIT_LIMIT                         8 NONE
CUST_EMAIL                             1699 NONE
CUST_TOTAL                                1 NONE
CUST_TOTAL_ID                             1 FREQUENCY
CUST_SRC_ID                               0 NONE
CUST_EFF_FROM                             1 NONE
CUST_EFF_TO                               0 NONE
CUST_VALID                                2 NONE

On voit qu'Oracle a calculé des histogrammes pour certaines colonnes mais pas toutes.

Lorsque j'exécute une requête listant les clients américains, le CBO lors du parsing, sait qu'1/3 de la table va être retournée et va donc préférer effectuer un Full Table Scan (FTS):

SQL> SET AUTOT TRACE EXP
SQL> SELECT *
  2  FROM customers
  3  WHERE country_id = 52790;

18520 ligne(s) sélectionnée(s).

-------------------------------------------------------------------------------
| Id  | Operation         | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |           | 18510 |  3253K|   406   (1)| 00:00:05 |
|*  1 |  TABLE ACCESS FULL| CUSTOMERS | 18510 |  3253K|   406   (1)| 00:00:05 |
-------------------------------------------------------------------------------

SQL> SET AUTOT OFF

Si je liste les clients saoudiens, le CBO choisira un accès via l'index sur COUNTRY_ID car il sait que je vais retourner un très faible pourcentage de la table:

SQL> SET AUTOT TRACE EXP
SQL> SELECT *
  2  FROM customers
  3  WHERE country_id = 52787;

75 ligne(s) sélectionnée(s).

------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name             | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |                  |   111 | 19980 |    25   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID| CUSTOMERS        |   111 | 19980 |    25   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | IDX_CUST_COUNTRY |   111 |       |     1   (0)| 00:00:01 |
------------------------------------------------------------------------------------

SQL> SET AUTOT OFF

Le CBO a cette connaissance sur les cardinalités retournées du fait qu'un histogramme a été calculé pour la colonne COUNTRY_ID.
Sans cet histogramme le CBO est incapable de savoir que selon le pays le nombre de clients peut être différent. En l'absence d'histogrammes le CBO estime que les données sont uniformément réparties et considère que le nombre de lignes à retourner correspond au nombre de lignes total de la table divisé par le nombre de valeurs distincts pour cette colonne:
NUM_ROWS/NUM_DISTINCT = 55500/19 = 2921 clients par pays

Maintenant que se passe-t-il quand on utilise une variable bindée pour la colonne COUNTRY_ID?
Ce qu'il faut savoir c'est qu'avant la 9i, le CBO n'avait aucune idée (au moment du parsing de la requête) de la valeur contenue dans la variable, et du coup pour faire ses estimations il utilisait des sélectivités constantes codées en dur (5% pour les clauses "<" ou ">").

Avec la 9i est arrivée la notion de BIND VARIABLE PEEKING qui est la fonctionalité permettant à Oracle de "peeker" la valeur des variables bindées au moment du parsing et de faire du coup une estimation des cardinalités comme s'il traitait une requête avec la valeur littéral dans la clause WHERE.
La preuve:

SQL> VARIABLE country_id number;

SQL> -- Récup des clients américains
SQL> execute :country_id := 52790;

SQL> SELECT *
  2  FROM customers
  3  WHERE country_id = :country_id;

-------------------------------------------------------------------------------
| Id  | Operation         | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |           | 18510 |  3253K|   406   (1)| 00:00:05 |
|*  1 |  TABLE ACCESS FULL| CUSTOMERS | 18510 |  3253K|   406   (1)| 00:00:05 |
-------------------------------------------------------------------------------

Regardez les cardinalités estimées dans la colonne ROWS. On a la même cardinalité que dans le plan où on mettait directement le numéro du pays dans la requête.

Maintenant je fais la même chose mais pour les clients saoudiens:

SQL> -- Récup des clients saoudiens
SQL> execute :country_id := 52787;

SQL> SELECT *
  2  FROM customers
  3  WHERE country_id = :country_id;

-------------------------------------------------------------------------------
| Id  | Operation         | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |           | 18510 |  3253K|   406   (1)| 00:00:05 |
|*  1 |  TABLE ACCESS FULL| CUSTOMERS | 18510 |  3253K|   406   (1)| 00:00:05 |
-------------------------------------------------------------------------------

Cette fois je n'ai pas d'accès via l'index alors que je suis censé récupérer un faible pourcentage de la table.
Que s'est-il donc passé? Pourquoi le CBO s'est-il trompé ici?
En fait, il ne s'est pas trompé. Le CBO a simplement pris le plan déjà dans la shared pool et l'a appliqué pour cette requête. Comme syntaxiquement la requête est identique le HARD PARSE n'est effectué que pour la première exécution. Ensuite, le plan calculé la première fois sera toujours pris en compte pour les autres exécutions. C'est le but des variables bindées, mais ici on découvre aussi quel est leur inconvénient.

Les bind variables sont à privilégier dans vos applications mais si vous avez des requêtes sur des colonnes dont la distribution des données n'est pas uniforme alors il vaut mieux ne pas utiliser de bind variable pour ces requêtes car comme dans l'exemple précédent vous risquez de vous retrouver avec un plan qui n'est pas optimal pour certaines exécutions. Le premier plan calculé sera toujours pris en compte jusqu'à ce qu'il soit vidé de la shared pool ou que le curseur ait été invalidé.

Le bind Peeking et la météo:
On m'a raconté une fois une anecdote qui permet d'illustrer les inconvénients du Bind Peeking.
Voici en résumé le problème qui a déjà fait l'objet d'une SR auprès du support Oracle:

Nous avons constaté que lorsqu'il fait beau notre application ne rencontre aucun problème de performance alors que lorsqu'il pleut nous faisons face à de gros problèmes de lenteur sur nos applications.

Ce problème a vraiment été remonté par un client d'Oracle au support.
Mais quel est donc le rapport entre la météo et le Bind Peeking?
En fait chez ce client on a des utilisateurs qui lancent plusieurs batch au cours de la journée. Un de ces utilisateurs en particulier lance un batch dont certaines requêtes font l'objet de Full Table Scan car ses requêtes récupèrent un grand pourcentage de données. Les autres utilisateurs lancent plutôt des batch qui génèrent des accès indéxés.
Que se passe-t-il lorsqu'il fait beau?
L'utilisateur dont le batch génère des FTS arrive en vélo le matin et donc arrive après les autres utilisateurs qui ont déjà lancé leur batch. Du coup, les plans avec les accès indéxés sont déjà dans la shared pool et partagés aux autres utilisateurs. Lorsqu'il pleut cet utilisateur préfère venir en bus, arrive donc avant tout le monde et lance son batch en premier.
Vous commencez à comprendre? Les requêtes de ce batch sont parsés en premier et donc on se retrouve avec des plans pleins de Full Table Scan en cache. Les autres utilisateurs, au moment où ils lancent leur batch, se mettent à récupérer ces plans d'exécution qui ne sont pas optimaux pour leurs requêtes. D'où le problème de performance lorsqu'il pleut.

CONCLUSION:
Lorsque vous utilisez des binds variables (mettre le paramètre CURSOR_SHARING à force par exemple a le même effet) ayez bien conscience des avantages mais aussi des effets dramatiques que ça peut engendrer. La première requête parsée conditionnera le plan qui sera utilisé pour toutes les autres requêtes.
Avec la 11g, Oracle a trouvé un moyen de remédier plus ou moins à ce problème via la fonctionnalité Adaptive Cursor Sharing (ACS). Mais ceci fera l'objet d'une autre post.