Introduction
Lorsqu'on doit optimiser une requête SQL, il arrive parfois qu'on ne comprenne absolument pas comment elle est exécutée par Oracle. Une requête qui devrait se dérouler en une seconde prend en réalité trente minutes sans que le plan d'exécution ne nous renseigne sur ce qui se passe. Dans ce cas là, pas d'hésitation, il faut impérativement utiliser une trace pour, comme son nom l'indique, tracer ce qui se passe réellement dans la base.

L'objectif de cet article est donc de bien vous faire prendre conscience de ce phénomène : un plan d'exécution peut être incomplet.


 
Points d'attention
Attention au niveau de votre trace, ne la laissez pas remplir un disque dur...



Base de tests
N'importe quelle base Oracle.



Exemples
============================================================================================
Des comportements différents entre la pré-prod et la prod
============================================================================================

J'ai deux bases, l'une de prod, l'une de pré-prod avec les tables suivantes (même volumétrie) :
     - test_obj01 : 2.5 millions d'enregistrements
          SQL> desc test_obj01
          Name                       Null?    Type
          ----------------------------------------- --------
          OBJECT_NAME                        VARCHAR2(128)
          SUBOBJECT_NAME                     VARCHAR2(128)
          OBJECT_NAME02                      VARCHAR2(128)
          ID_FK                              NUMBER
          ID                                 NUMBER
          
          SQL> select count(*) from test_obj01;
          COUNT(*)
          ----------
          2512736
         
     - test_delete, une table de seulement sept enregistrements
          SQL> select * from test_delete order by id;  
              ID OWNER
          ---------- ----------
               1 HR
               2 HR02
               3 HR03
               4 HR04
               5 HR05
               6 SYSTEM
               7 SYS

          7 rows selected.

En production
Un DELETE sur la plus petite table s'exécute en 12 centièmes de secondes; normal vu sa taille.

          SQL> set timing on
          SQL> delete test_delete where id = 3;
          1 row deleted.
          Elapsed: 00:00:00.12
               
Son plan d'exécution est on ne peut plus simple.
          SQL> explain plan for delete test_delete where id = 3;
          SQL> select * from table(dbms_xplan.display);
          Execution Plan
          ----------------------------------------------------------
          Plan hash value: 1498343968

          -----------------------------------------------------------------------------------
          | Id  | Operation       | Name      | Rows  | Bytes | Cost (%CPU)| Time      |
          -----------------------------------------------------------------------------------
          |   0 | DELETE STATEMENT   |          |    1 |    13 |    1   (0)| 00:00:01 |
          |   1 |  DELETE        | TEST_DELETE  |      |      |           |      |
          |*  2 |   INDEX UNIQUE SCAN| SYS_C0012912 |    1 |    13 |    1   (0)| 00:00:01 |
          -----------------------------------------------------------------------------------

          Predicate Information (identified by operation id):
          ---------------------------------------------------
             2 - access("ID"=3)
          

En pré-prod
Le DELETE met 32 minutes!!!!!

          SQL> delete test_delete where id = 3;
          1 row deleted.
          Elapsed: 00:32:37.79

Quel est le plan d'exécution dans ce cas? Surprise, il est absolument identique puisqu'on a le même Plan hash value (1498343968) que celui de la prod. Pire, il est même faux car Oracle nous dit que ce DELETE doit prendre seulement 1 seconde!
          SQL> explain plan for delete test_delete where id = 3;
          Explained.
          
          SQL> select * from table(dbms_xplan.display);
          Execution Plan

          ------------------------------------------------------------
          Plan hash value: 1498343968

          --------------------------------------------------------------------------------
          | Id  | Operation       | Name      | Rows  | Bytes | Cost (%CPU)| Time      |
          ----------------------------------------------------------------------------------
          |   0 | DELETE STATEMENT   |          |    1 |    13 |    1   (0)| 00:00:01 |
          |   1 |  DELETE        | TEST_DELETE  |      |      |           |      |
          |*  2 |   INDEX UNIQUE SCAN| SYS_C0012912 |    1 |    13 |    1   (0)| 00:00:01 |
          ----------------------------------------------------------------------------------

          Predicate Information (identified by operation id):
          ---------------------------------------------------
             2 - access("ID"=3)
          
          14 rows selected.
          
         
============================================================================================
Que nous dit la trace 10046?
============================================================================================

Pour comprendre ce qui peut se passer, nous recommençons nos tests avec cette fois une trace 10046 pour voir, d'un point de vue interne, ce que fait réellement Oracle lors du DELETE. Nous positionnons cette trace au niveau 12, soit le plus verbeux (attention à ne pas remplir votre disque dur!).

Tests en production :
          SQL> ALTER SESSION SET timed_statistics = TRUE;
          SQL> ALTER SESSION SET max_dump_file_size = unlimited;
          SQL> ALTER SESSION SET TRACEFILE_IDENTIFIER = 'TEST_DELETE01.trc';
          SQL> ALTER SESSION SET events '10046 trace name context forever, level 12';
          SQL> delete test_delete where id = 3;
          1 row deleted.
Ne surtout pas oublier de désactiver la trace après le test.         
          SQL> ALTER SESSION SET events '10046 trace name context off';
         
Attention, avec Oracle 11.1, les traces ne sont plus dans le répertoire identifié par le paramètre user_dump_dest, il faut dorénavant utiliser la vue V$DIAG_INFO. A noter que le nom du fichier trace généré est préfixé d'office par Oracle avec l'id de la base.
          SQL> sho parameter user_dump
          NAME              TYPE     VALUE
          ------------------------------------ ----------- -----------------------
          user_dump_dest    string     /u01/app/oracle/product/12.2/db_1/rdbms/log
         
          SQL> select INST_ID NAME, VALUE from v$diag_info where NAME = 'Diag Trace';
             INST_ID NAME         VALUE                                             
          ---------- -------------------- -------------------------------------------
               1 Diag Trace        /u01/app/oracle/diag/rdbms/orcl12c/orcl12c/trace 
          
         Unix$ ls -l *DE*
          -rw-r----- 1 oracle oinstall 60402 Feb  3 08:09 orcl12c_ora_4784_TEST_DELETE01.trc
          -rw-r----- 1 oracle oinstall 11976 Feb  3 08:09 orcl12c_ora_4784_TEST_DELETE01.trm
          
Le contenu brut du fichier orcl12c_ora_4784_TEST_DELETE01.trc est difficilement exploitable, idem pour le .trm. Nous utilisons l'utilitaire TKPROF pour le rendre humainement lisible.
                    Unix$ tkprof orcl12c_ora_4784_TEST_DELETE01.trc orcl12c_ora_4784_TEST_DELETE01.txt

Le fichier trace contient près de dix SELECT dans les tables du dictionnaire de données avant d'arriver au DELETE proprement dit; il s'agit des SELECT liés au parsing de la requête, chose qui ne nous intéresse pas. Je copie ici le contenu du fichier après le DELETE : rien de spécial. Je mets en bleu foncé ce qui me semble important.
          ...
          SQL ID: 9dh924x7phvkz Plan Hash: 699389291
          
          delete test_delete
          where
           id = 3

          call     count       cpu    elapsed       disk      query    current        rows
          ------- ------  -------- ---------- ---------- ---------- ----------  ----------
          Parse        1      0.00       0.00          0          2          0           0
          Execute      1      0.00       0.00          0          7          3           1
          Fetch        0      0.00       0.00          0          0          0           0
          ------- ------  -------- ---------- ---------- ---------- ----------  ----------
          total        2      0.00       0.00          0          9          3           1
          
          Misses in library cache during parse: 1
          Optimizer mode: ALL_ROWS
          Parsing user id: 128  
          Number of plan statistics captured: 1
          
          Rows (1st) Rows (avg) Rows (max)  Row Source Operation
          ---------- ---------- ----------  --------------------
                   0          0          0  DELETE  TEST_DELETE (cr=7 pr=0 pw=0 time=165 us starts=1)
                   1          1          1   TABLE ACCESS FULL TEST_DELETE (cr=7 pr=0 pw=0 time=60 us starts=1 cost=3 size=3 card=1)
         
          Elapsed times include waiting on following events:
            Event waited on                             Times   Max. Wait  Total Waited
            ----------------------------------------   Waited  ----------  ------------
            SQL*Net message to client                       1        0.00          0.00
            SQL*Net message from client                     1       11.38         11.38
          ********************************************************************************
          ...


En pré-prod
          SQL> ALTER SESSION SET timed_statistics = TRUE;
          SQL> ALTER SESSION SET max_dump_file_size = unlimited;
          SQL> ALTER SESSION SET TRACEFILE_IDENTIFIER = 'TEST_DELETE02.trc';
          SQL> ALTER SESSION SET events '10046 trace name context forever, level 12';
          SQL> delete test_delete where id = 3;
               1 row deleted.
          SQL> ALTER SESSION SET events '10046 trace name context off';
         
Que contient le nouveau fichier de traces? Beaucoup beaucoup plus de choses! J'enlève plusieurs lignes pour ne garder que la substantifique moelle!
          ...
          SQL ID: 9dh924x7phvkz Plan Hash: 2177063714
          
          delete test_delete
          where
           id = 3
          ...
          

BINGO!!!!!!!!!!! Il y a un SELECT ajouté par Oracle dans la table test_obj01. A quoi sert-il? Un DELETE, un SELECT ensuite... cela sent la foreign key!
          SQL ID: 363hgu7bsadqz Plan Hash: 1655282428
          
          select /*+ all_rows */ count(1)
          from
           "HR"."TEST_OBJ01" where "ID_FK" = :1
         
          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        1      0.21       0.23      29563      30510          0           1
          ------- ------  -------- ---------- ---------- ---------- ----------  ----------
          total        3      0.21       0.23      29563      30510          0           1
          
          Misses in library cache during parse: 1
          Misses in library cache during execute: 1
          Optimizer mode: ALL_ROWS
          Parsing user id: SYS   (recursive depth: 1)
          Number of plan statistics captured: 1
          
          Rows (1st) Rows (avg) Rows (max)  Row Source Operation
          ---------- ---------- ----------  --------------------
                   1          1          1  SORT AGGREGATE (cr=30510 pr=29563 pw=0 time=235077 us starts=1)
             1200000    1200000    1200000   TABLE ACCESS FULL TEST_OBJ01 (cr=30510 pr=29563 pw=0 time=187895 us starts=1 cost=8291 size=1076886 card=358962)
          
          
          Elapsed times include waiting on following events:
            Event waited on                             Times   Max. Wait  Total Waited
            ----------------------------------------   Waited  ----------  ------------
            db file scattered read                        345        0.00          0.04
            db file sequential read                        35        0.00          0.00
          ********************************************************************************
          

============================================================================================
Analyse des contraintes d'intégrité
============================================================================================

Pour finaliser notre analyse, interrogeons la vue DBA_CONSTRAINTS sur la table TEST_OBJ01 puisque c'est elle qui renferme la clé du mystère.

          SQL> > select CONSTRAINT_NAME, CONSTRAINT_TYPE, R_OWNER, R_CONSTRAINT_NAME from dba_constraints where owner = 'HR' and table_name = 'TEST_OBJ01';
          CONSTRAINT_NAME            C      R_OWN R_CONSTRAINT_NAME
          ------------------------------ - ----- ------------------------------
          PK_TEST_OBJ01_ID           P
          FK_TEST_OBJ01_OWNER        R      HR    PK_TEST_DELETE_ID

Tiens, une contraintes de type R, soit une FOREIGN KEY :-)
Cette FOREIGN KEY de la table TEST_OBJ01 porte sur la colonne ID_FK.
          SQL> select * from dba_cons_columns where CONSTRAINT_NAME = 'FK_TEST_OBJ01_OWNER';
          OWNER CONSTRAINT_NAME              TABLE_NAME COLUM   POSITION
          ----- ------------------------------ ---------- ----- --------
          HR    FK_TEST_OBJ01_OWNER          TEST_OBJ01 ID_FK        1

Vers quelle table pointe-t-elle? Il faut utiliser la colonne R_CONSTRAINT_NAME de la table DBA_CONSTRAINTS pour identifier la table de référence, la table maître.
          SQL> select table_name, CONSTRAINT_TYPE from dba_constraints where owner = 'HR' and CONSTRAINT_NAME = 'PK_TEST_DELETE_ID';
          TABLE_NAME         C
          -------------------- -
          TEST_DELETE         P

          SQL> select * from dba_cons_columns where CONSTRAINT_NAME = 'PK_TEST_DELETE_ID';  
          OWNER CONSTRAINT_NAME          TABLE_NAME           COLUM   POSITION
          ----- ------------------------------ -------------------- ----- ----
          HR    PK_TEST_DELETE_ID        TEST_DELETE           ID          1

Le résultat est clair : la colonne ID_FK de la table TEST_OBJ01 référence la colonne ID de la table TEST_DELETE via une foreign key. Donc si on fait un DELETE dans TEST_DELETE, un SELECT est fait dans TEST_OBJ01 pour s'assurer que ce DELETE peut être fait. Si la valeur à supprimer est référencée, Oracle interdit le DELETE sauf si la foreign key a été créée avec l'option ON DELETE CASCADE mais cela est une autre histoire car tous les enregistrements de la table fille seront supprimés avec celui de la table de référence.
Corollaire de ceci : la pré-prod n'est pas iso par rapport à la prod, la FK existe en pré-prod mais pas en prod car il s'agit d'une mise à jour en cours de test.



Voilà, l'objectif est atteint, montrer que quand il exécute un ordre SQL, Oracle peut en exécuter plusieurs autres sous le capot, que ceux-ci peuvent être très longs et qu'en plus ils n'apparaissent pas dans le plan d'exécution, d'où l'obligation d'utiliser une trace.