dimanche 28 avril 2013

Régler un problème de performance en 5 étapes

Faire face à un problème de performance peut être une tâche extrêmement difficile car chaque problème peut avoir une nature et des causes diverses. Toutefois avec une bonne approche et une connaissance des outils à notre disposition on peut y faire face un peu plus aisément.

La méthode que j'utilise est une méthode très connue chez les experts Oracle. Elle est composée des 5 étapes suivantes:
1) Définition du problème
2) Investigation
3) Analyse
4) Résolution
5) Implementation

Je vais tenter à travers cet article d'expliquer cette approche et de l'illustrer avec un exemple de problème de performance que j'ai eu à régler il y' a quelques mois.

Etape 1: Définition du problème

Cette étape consiste à poser à son interlocuteur (un utilisateur, un développeur, un client etc.) les bonnes questions afin de définir le problème en question. On est ici un peu dans la peau du médecin qui, pour être sûr d'avoir bien compris ce dont souffre le patient, lui pose un certain nombre de questions.
On va se demander ici si le problème est en cours ou pas, si le problème de performance est général ou bien limité à un module applicatif. On va essayer de savoir si ce problème s'est déjà produit par le passé, si des changements ont eu lieu au niveau de l'application (nouvelle version applicative), au niveau de la base (ex:migration, modification de paramètres d'instance), au niveau de l'OS etc.
Toutes ces questions vont permettre de bien diagnostiquer la situation en forçant notre interlocuteur à bien exprimer son problème.

Exemple:
J'ai reçu un mail il y'a quelques mois d'un chef de projet qui se plaignait que la base de prod était "lente". Pour bien identifier son problème j'avais besoin de comprendre ce qu'il entendait par "lent". Lorsqu'il m'a dit "Depuis midi nos process de calculs mettent plus de temps à s'exécuter que d'habitude" j'avais déjà là quelque chose de plus précis. Ensuite en lui posant d'autres questions sur notamment si des changements avaient été opérés sur la base ou autre, j'ai pu découvrir que la volumétrie de données traitées par le programme avait en effet augmenté. Ce genre d'informations hyper importantes ne sont souvent pas mentionnées par nos interlocuteurs lorsqu'on nous fait part d'un problème de performance. C'est à nous de leur tirer les vers du nez...

Etape 2: Investigation

Une fois que le problème est bien défini vous devez vêtir l'imperméable du lieutenant Columbo et tenter de collecter le maximum d'information permettant de quantifier le problème. Au cours de cette étape vous allez choisir (en fonction des symptômes et des info récupérées à l'étape précédente) d'utiliser le ou les outils que vous avez à votre disposition.
Si par un exemple le problème de performance a eu lieu dans le passé vous pouvez éditer un rapport AWR ou statspacks. Si le problème est en cours vous allez plutôt requêter les vues V$SESSION et V$SQL pour voir les sessions actives et les évènement sur lesquelles elles sont en attente. A cette étape il est possible de constater qu'en réalité le problème de performance n'existe pas ou en tout cas pas lié à la base de données.

Exemple:
Pour étudier le problème de performance évoqué à l'étape précédente j'avais opté pour une génération de rapport AWR entre midi et 15h car mon échange avec le chef de projet m'avait permis de cerner le problème sur cette plage horaire.
Voici un extrait du rapport obtenu à l'époque:
               Snap Id      Snap Time      Sessions Curs/Sess
             --------- ------------------- -------- ---------
 Begin Snap:     16906 02-Jul-12 12:00:56       490      14.2
   End Snap:     16909 02-Jul-12 15:00:15       539      17.5
    Elapsed:              179.33 (mins)
    DB Time:            4,896.89 (mins)
 
 Top 5 Timed Events                                         Avg %Total
 ~~~~~~~~~~~~~~~~~~                                        wait   Call
 Event                                 Waits    Time (s)   (ms)   Time Wait Class
 ------------------------------ ------------ ----------- ------ ------ ----------
 CPU time                                        206,506          70.3
 db file sequential read           3,514,166      28,081      8    9.6   User I/O
 log file sync                     1,260,469      13,534     11    4.6     Commit
 latch: cache buffers chains       1,641,252      10,941      7    3.7 Concurrenc
 log file parallel write             912,993       4,260      5    1.4 System I/O
 
 Time Model Statistics              DB/Inst: LNSX11/LNSX11  Snaps: 16906-16909
 -> Total time in database user-calls (DB Time): 293813.4s
 -> Statistics including the word "background" measure background process
    time, and so do not contribute to the DB time statistic
 -> Ordered by % or DB time desc, Statistic name
 
 Statistic Name                                       Time (s) % of DB Time
 ------------------------------
------------ ------------------ ------------
 sql execute elapsed time                            270,349.0         92.0
 DB CPU                                              206,505.8         70.3
 parse time elapsed                                    4,037.1          1.4
 PL/SQL execution elapsed time                         2,661.8           .9
 hard parse elapsed time                               2,155.4           .7
 RMAN cpu time (backup/restore)                          440.9           .2
 PL/SQL compilation elapsed time                         424.5           .1
 connection management call elapsed time                 244.6           .1
 hard parse (sharing criteria) elapsed time              115.9           .0
 repeated bind elapsed time                               60.6           .0
 inbound PL/SQL rpc elapsed time                          59.5           .0
 hard parse (bind mismatch) elapsed time                  56.9           .0
 sequence load elapsed time                               14.9           .0
 failed parse elapsed time                                 0.1           .0
 DB time                                             293,813.4          N/A
 background elapsed time                               7,240.5          N/A
 background cpu time                                     844.5          N/A
           -------------------------------------------------------------
 

On  note que durant ces 3 heures on a eu 81 heures de DB time.

La section "Top 5 Timed Events" indique que 70% du DB Time concerne du CPU Time. La partie "Time Model Statistics", elle, montre que 92% de ce DB Time est lié à l'exécution de code SQL.
Pour avoir plus d'informations sur les requêtes SQL qui sont responsables de cette consommation accrue de DB Time il faut aller regarder du côté de la section "SQL ordered by Elapsed Time":
SQL ordered by Elapsed Time        DB/Inst: LNSX11/LNSX11  Snaps: 16906-16909
-> Resources reported for PL/SQL code includes the resources used by all SQL
   statements called by the code.
-> % Total DB Time is the Elapsed Time of the SQL statement divided
   into the Total Database Time multiplied by 100
-> Total DB Time (s):         293,813
-> Captured SQL account for      66.1% of Total

  Elapsed      CPU                  Elap per  % Total
  Time (s)   Time (s)  Executions   Exec (s)  DB Time    SQL Id
---------- ---------- ------------ ---------- ------- -------------
    86,698     69,051          674      128.6    29.5 5ydxnct2swxau
Module: LNS_X01_cal.exe
 Select HIR_MTM,ROO_ID,sja_fieldid FIELDID, (Select STV_VALUE from MUT_STATUS_
VALOSIMPLE, MUT_STATUS_PONDERATION, MUTATION Where STV_DATE=(Select Max(STV_DATE
) From MUT_STATUS_VALOSIMPLE, MUT_STATUS_PONDERATION, MUTATION Where STV_OBJ_ID
=SJA_ID And STV_DATE <=TO_DATE(:"SYS_B_00", :"SYS_B_01") And STV_STATUS_ID=PON_S

    45,771     36,420          458       99.9    15.6 g0kfhsfnh3kvv
Module: LNS_X01_cal.exe
 Select HIR_MTM,ROO_ID,sja_fieldid FIELDID, (Select STV_VALUE from MUT_STATUS_
VALOSIMPLE, MUT_STATUS_PONDERATION, MUTATION Where STV_DATE=(Select Max(STV_DATE
) From MUT_STATUS_VALOSIMPLE, MUT_STATUS_PONDERATION, MUTATION Where STV_OBJ_ID
=SJA_ID And STV_DATE <=TO_DATE(:"SYS_B_00", :"SYS_B_01") And STV_STATUS_ID=PON_S 
Les 2 requêtes ci dessus sont les requêtes à tuner car elles sont responsables à elles deux de 45% du DB Time (29.5+15.6).


Etape 3: Analyse

Après avoir collecté les informations permettant d'identifier le problème il faut entrer dans une étape d'analyse afin de trouver les causes principales de la lenteur de nos requêtes. Là aussi, une bonne connaissance des outils à notre disposition est primordial (traces 10046 et 10053, plans d'exécution, vues V$ etc.).
Cette étape est à la fois la plus difficile et la plus passionnante.

Concernant  notre exemple on sait grâce à l'étape précédente que le problème de performance est lié essentiellement à 2 requêtes. Il faut donc analyser l'exécution et le plan de ces 2 requêtes pour identifier la cause de la lenteur.

Analyse de la première requête (sql_id=5ydxnct2swxau)

Le rapport AWR nous indique que cette requête s'exécute en moyenne en 128.6 secondes. Avec 674 exécutions, le temps total d'exécution s'élève à  86 698 secondes (soit 24 heures).
Jetons un œil aux statistiques d'exécutions actuelles pour cette requête (stats récupérées dans V$SQL):
SQL> @sql_find_stats
Enter value for sql_text:
Enter value for sql_id: 5ydxnct2swxau

SQL_ID         CHILD PLAN_HASH_VALUE      EXECS ROWS_PROCESSED  AVG_ETIME    AVG_PIO    AVG_LIO
------------- ------ --------------- ---------- -------------- ----------  ---------- ----------
5ydxnct2swxau      0      3968018239        867        2197243     123.92         .49  1,632,031

Nous avons un temps d'exécution moyen de 123.92 secondes ce qui correspond pratiquement au temps d'exécution observé dans le rapport AWR.

Regardons de plus près l'historique d'exécution pour cette requête (grâce à la vue DBA_HIST_SQLSTAT):
 SQL> @awr_plan_change
Enter value for sql_id: 5ydxnct2swxau
Enter value for instance_number:

    SNAP_ID   NODE BEGIN_INTERVAL_TIME            SQL_ID        PLAN_HASH_VALUE        EXECS    AVG_ETIME        AVG_LIO    AVG_PIO     AVG_ROWS
---------- ------ ------------------------------ ------------- --------------- ------------ ------------ -------------- ---------- ------------
     16096      1 29-MAY-12 07.00.12.099 AM      5ydxnct2swxau      3968018239           92       36.012    2,100,168.0      54.43          848
     16120      1 30-MAY-12 07.00.08.939 AM      5ydxnct2swxau                           25       28.695    1,494,734.7     106.84          601
     16144      1 31-MAY-12 07.00.09.862 AM      5ydxnct2swxau                           67       33.522    1,986,261.7      44.06          800
     16262      1 05-JUN-12 07.00.03.542 AM      5ydxnct2swxau                           23       15.572      801,967.7      52.65          322
     16311      1 07-JUN-12 08.00.55.576 AM      5ydxnct2swxau                          151       44.639    2,538,922.9      36.52        1,020
     16428      1 12-JUN-12 07.00.15.397 AM      5ydxnct2swxau                           55       31.000    1,682,545.4     102.27          671
     16476      1 14-JUN-12 07.00.58.869 AM      5ydxnct2swxau                           62       33.211    1,841,182.8      79.66          735
     16618      1 20-JUN-12 07.00.09.276 AM      5ydxnct2swxau                           36       27.819    1,522,616.9     129.00          607
     16737      1 25-JUN-12 08.00.29.501 AM      5ydxnct2swxau                           12       27.617    1,628,256.7        .00          648
     16844      1 29-JUN-12 07.00.54.189 PM      5ydxnct2swxau                          492       84.000    4,824,879.5       4.89        1,837
     16845      1 29-JUN-12 08.00.57.512 PM      5ydxnct2swxau                          710       87.038    4,153,332.8        .14        1,601
     16846      1 29-JUN-12 09.00.00.273 PM      5ydxnct2swxau                          764       78.419    4,199,976.2        .00        1,593
     16847      1 29-JUN-12 10.00.06.863 PM      5ydxnct2swxau                          758       76.995    4,426,137.8        .05        1,691
     16848      1 29-JUN-12 11.00.10.768 PM      5ydxnct2swxau                          774       75.453    4,432,480.4        .01        1,689
     16849      1 30-JUN-12 12.00.13.539 AM      5ydxnct2swxau                          618       96.493    5,709,939.6        .00        2,197
     16850      1 30-JUN-12 01.00.16.443 AM      5ydxnct2swxau                          510      110.112    6,552,217.1        .00        2,515
     16851      1 30-JUN-12 02.00.19.187 AM      5ydxnct2swxau                          496      111.173    6,393,527.4        .00        2,447
     16901      1 02-JUL-12 06.00.20.638 AM      5ydxnct2swxau                          564       65.402    3,961,601.9      15.80        1,499
     16904      1 02-JUL-12 09.00.42.918 AM      5ydxnct2swxau                          680       74.424    4,268,174.0        .10        1,623
     16905      1 02-JUL-12 10.00.49.137 AM      5ydxnct2swxau                          644       85.137    4,495,420.0        .05        1,718
     16906      1 02-JUL-12 11.00.52.661 AM      5ydxnct2swxau                           87      127.208    6,788,947.7        .00        2,634
     16907      1 02-JUL-12 12.00.56.370 PM      5ydxnct2swxau                            3       62.627    3,607,740.0        .00        1,335
     16908      1 02-JUL-12 01.00.01.946 PM      5ydxnct2swxau                          347      121.837    6,638,634.2        .12        2,552
     16909      1 02-JUL-12 02.00.09.803 PM      5ydxnct2swxau                          324      136.520    6,896,529.5        .24        2,660
     16910      1 02-JUL-12 03.00.15.936 PM      5ydxnct2swxau                          230      107.049    5,809,572.0       1.39        2,228
 On peut noter qu'il n'y a pas de problème d'instabilité de plan pour cett requête puisque le même plan est utilisé à chaque fois. 
Il faut donc analyser de plus près ce plan d'exécution.
Tout d'abord vérifions qu'on obtient bien le même plan si on exécute cette requête de manière isolée.
Comme cette requête utilise des binds variables nous devons tenter de récupérer les valeurs enregistrées lors de l'opération de bind peeking en requêtant la vue V$SQL_BIND_CAPTURE:
 col VALUE_STRING for A20
select name,position,datatype_string,value_string
from V$SQL_BIND_CAPTURE where sql_id='5ydxnct2swxau';

NAME                             POSITION DATATYPE_STRING VALUE_STRING
------------------------------ ---------- --------------- --------------------
:SYS_B_00                               1 VARCHAR2(32)    29-06-2012
:SYS_B_01                               2 VARCHAR2(32)    dd-mm-yyyy
:SYS_B_02                               3 NUMBER          2
:SYS_B_03                               4 NUMBER          1
:SYS_B_04                               5 NUMBER          2
:SYS_B_05                               6 NUMBER          1
:SYS_B_06                               7 NUMBER          164826982
:SYS_B_07                               8 VARCHAR2(32)    29-06-2012
:SYS_B_08                               9 VARCHAR2(32)    dd-mm-yyyy
:SYS_B_09                              10 VARCHAR2(32)    29-06-2012
:SYS_B_10                              11 VARCHAR2(32)    dd-mm-yyyy
:SYS_B_11                              12 VARCHAR2(32)    29-06-2012
:SYS_B_12                              13 VARCHAR2(32)    dd-mm-yyyy
:SYS_B_13                              14 NUMBER          50000
:SYS_B_14                              15 NUMBER          40001
:SYS_B_15                              16 VARCHAR2(32)    29-06-2012
:SYS_B_16                              17 VARCHAR2(32)    dd-mm-yyyy
:SYS_B_17                              18 NUMBER          14
Maintenant qu'on a les dernières valeurs peekées on peut remplacer dans la requête les binds variables par les valeurs obtenues:
Select HIR_MTM,
       ROO_ID,
       sja_fieldid FIELDID,
       (Select STV_VALUE
          from MUT_STATUS_VALOSIMPLE, MUT_STATUS_PONDERATION, MUTATION
         Where STV_DATE =
               (Select Max(STV_DATE)
                  From MUT_STATUS_VALOSIMPLE,
                       MUT_STATUS_PONDERATION,
                       MUTATION
                 Where STV_OBJ_ID = SJA_ID
                   And STV_DATE <= TO_DATE('29-06-2012', 'dd-mm-yyyy')
                   And STV_STATUS_ID = PON_STATUS_ID
                   And MUT_ID = STV_STATUS_ID
                   And MUT_TYPESTATUS_ID = 2
                   And MUT_LASTFLAG = 1)
           And STV_OBJ_ID = SJA_ID
           And STV_STATUS_ID = PON_STATUS_ID
           And MUT_ID = STV_STATUS_ID
           And MUT_TYPESTATUS_ID = 2
           And MUT_LASTFLAG = 1) POND,
       SPO_SPOT
  From MUT_HISTO_ROOT histo, MUT_SOUS_JACENT, MUT_ROOT2, SPOT
 Where SJA_PARENT_ID = 164826982
   And SJA_STARTDATE <= TO_DATE('29-06-2012', 'dd-mm-yyyy')
   And (SJA_STOPDATE >= TO_DATE('29-06-2012', 'dd-mm-yyyy') or
       SJA_STOPDATE is NULL)
   And TRUNC(histo.LYX_DAY(+)) = TO_DATE('29-06-2012', 'dd-mm-yyyy')
   And SJA_ROOTID_SJ = histo.LYX_OWNER_ID(+)
   And HIR_TYPE_ID(+) = 50000
   And HIR_TIMETYPE_ID(+) = 40001
   And ROO_ID = SJA_ROOTID_SJ
   AND SPOT.LYX_DAY(+) = TO_DATE('29-06-2012', 'dd-mm-yyyy')
   AND SPO_DEVISE_A(+) = 14
   AND SPO_DEVISE_B(+) = ROO_DEVISE_ID;

1680 rows selected.

Elapsed: 00:01:12.56

SQL> select * from table(dbms_xplan.display_cursor(null,null,'iostats last'));

SQL_ID  du7t6514za5rs, child number 1
-------------------------------------
Plan hash value: 3968018239

--------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                          | Name                      | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
--------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                   |                           |      1 |        |   1680 |00:00:00.20 |   10993 |
|   1 |  NESTED LOOPS                      |                           |   1680 |      1 |   1680 |00:01:09.95 |    4752K|
|   2 |   NESTED LOOPS                     |                           |   1680 |      1 |   1782 |00:01:09.91 |    4747K|
|   3 |    TABLE ACCESS BY INDEX ROWID     | MUT_STATUS_VALOSIMPLE     |   1680 |      1 |   1782 |00:01:09.88 |    4743K|
|*  4 |     INDEX RANGE SCAN               | IDX_OBJ_DATE              |   1680 |      1 |   1782 |00:01:09.85 |    4741K|
|   5 |      SORT AGGREGATE                |                           |   1680 |      1 |   1680 |00:01:09.80 |    4738K|
|   6 |       NESTED LOOPS                 |                           |   1680 |    529 |   4351 |00:01:09.79 |    4738K|
|   7 |        NESTED LOOPS                |                           |   1680 |    528 |   4623 |00:01:09.67 |    4724K|
|   8 |         TABLE ACCESS BY INDEX ROWID| MUT_STATUS_VALOSIMPLE     |   1680 |    528 |   4623 |00:01:09.59 |    4715K|
|*  9 |          INDEX SKIP SCAN           | IDX_OBJ_DATE              |   1680 |    528 |   4623 |00:01:09.54 |    4710K|
|* 10 |         INDEX UNIQUE SCAN          | PK_POND                   |   4623 |      1 |   4623 |00:00:00.06 |    9359 |
|* 11 |        TABLE ACCESS BY INDEX ROWID | MUTATION                  |   4623 |      1 |   4351 |00:00:00.10 |   13982 |
|* 12 |         INDEX UNIQUE SCAN          | PK_MUTATION               |   4623 |      1 |   4623 |00:00:00.06 |    9359 |
|* 13 |    INDEX UNIQUE SCAN               | PK_POND                   |   1782 |      1 |   1782 |00:00:00.02 |    3677 |
|* 14 |   TABLE ACCESS BY INDEX ROWID      | MUTATION                  |   1782 |      1 |   1680 |00:00:00.04 |    5459 |
|* 15 |    INDEX UNIQUE SCAN               | PK_MUTATION               |   1782 |      1 |   1782 |00:00:00.02 |    3677 |
|  16 |  NESTED LOOPS OUTER                |                           |      1 |    127 |   1680 |00:00:00.20 |   10993 |
|* 17 |   HASH JOIN OUTER                  |                           |      1 |     97 |   1680 |00:00:00.02 |    3406 |
|  18 |    NESTED LOOPS                    |                           |      1 |     97 |   1680 |00:00:00.01 |    3400 |
|* 19 |     TABLE ACCESS BY INDEX ROWID    | MUT_SOUS_JACENT           |      1 |     97 |   1680 |00:00:00.01 |      38 |
|* 20 |      INDEX RANGE SCAN              | IDX_SOUS_JACENT_PARENT_ID |      1 |    101 |   1791 |00:00:00.01 |       6 |
|  21 |     TABLE ACCESS BY INDEX ROWID    | MUT_ROOT2                 |   1680 |      1 |   1680 |00:00:00.01 |    3362 |
|* 22 |      INDEX UNIQUE SCAN             | PK_ROOT2                  |   1680 |      1 |   1680 |00:00:00.01 |    1682 |
|  23 |    TABLE ACCESS BY INDEX ROWID     | SPOT                      |      1 |      8 |     21 |00:00:00.01 |       6 |
|* 24 |     INDEX RANGE SCAN               | PK_SPOT                   |      1 |      8 |     21 |00:00:00.01 |       4 |
|  25 |   TABLE ACCESS BY INDEX ROWID      | MUT_HISTO_ROOT            |   1680 |      1 |   1563 |00:00:00.18 |    7587 |
|* 26 |    INDEX RANGE SCAN                | IDX_MHR_LOHTHTLD          |   1680 |      1 |   1563 |00:00:00.16 |    6024 |
--------------------------------------------------------------------------------------------------------------------------

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

   4 - access("STV_DATE"= AND "STV_OBJ_ID"=:B1)
   9 - access("STV_OBJ_ID"=:B1 AND "STV_DATE"<=TO_DATE(:SYS_B_00,:SYS_B_01))
       filter("STV_OBJ_ID"=:B1)
  10 - access("STV_STATUS_ID"="PON_STATUS_ID")
  11 - filter(("MUT_TYPESTATUS_ID"=:SYS_B_02 AND "MUT_LASTFLAG"=:SYS_B_03))
  12 - access("MUT_ID"="STV_STATUS_ID")
  13 - access("STV_STATUS_ID"="PON_STATUS_ID")
  14 - filter(("MUT_TYPESTATUS_ID"=:SYS_B_04 AND "MUT_LASTFLAG"=:SYS_B_05))
  15 - access("MUT_ID"="STV_STATUS_ID")
  17 - access("SPO_DEVISE_B"="ROO_DEVISE_ID")
  19 - filter(("SJA_STARTDATE"<=TO_DATE(:SYS_B_07,:SYS_B_08) AND ("SJA_STOPDATE">=TO_DATE(:SYS_B_09,:SYS_B_10) OR
              "SJA_STOPDATE" IS NULL)))
  20 - access("SJA_PARENT_ID"=:SYS_B_06)
  22 - access("ROO_ID"="SJA_ROOTID_SJ")
  24 - access("SPOT"."LYX_DAY"=TO_DATE(:SYS_B_15,:SYS_B_16) AND "SPO_DEVISE_A"=:SYS_B_17)
  26 - access("SJA_ROOTID_SJ"="HISTO"."LYX_OWNER_ID" AND "HIR_TIMETYPE_ID"=:SYS_B_14 AND "HIR_TYPE_ID"=:SYS_B_13)
       filter(TRUNC(INTERNAL_FUNCTION("HISTO"."LYX_DAY"))=TO_DATE(:SYS_B_11,:SYS_B_12))
La requête a mis plus d'une minute pour s'exécuter et a généré 4752K logical reads. Le problème se situe au niveau au niveau de l'INDEX SKIP SKAN de l'index  IDX_OBJ_DATE (operation 9). Cette opération génère à elle seule 4710K logical reads. Cet index permet d'accéder à la table MUT_STATUS_VALOSIMPLE qui est appelée au niveau de la scalar subquery de la requête.
Si on exécute la requête sans la scalar subquery le problème de performance ne se produit plus:
 Select HIR_MTM,
       ROO_ID,
       sja_fieldid FIELDID,
       SPO_SPOT
  From MUT_HISTO_ROOT histo, MUT_SOUS_JACENT, MUT_ROOT2, SPOT
 Where SJA_PARENT_ID = 164826982
   And SJA_STARTDATE <= TO_DATE('29-06-2012', 'dd-mm-yyyy')
   And (SJA_STOPDATE >= TO_DATE('29-06-2012', 'dd-mm-yyyy') or
       SJA_STOPDATE is NULL)
   And TRUNC(histo.LYX_DAY(+)) = TO_DATE('29-06-2012', 'dd-mm-yyyy')
   And SJA_ROOTID_SJ = histo.LYX_OWNER_ID(+)
   And HIR_TYPE_ID(+) = 50000
   And HIR_TIMETYPE_ID(+) = 40001
   And ROO_ID = SJA_ROOTID_SJ
   AND SPOT.LYX_DAY(+) = TO_DATE('29-06-2012', 'dd-mm-yyyy')
   AND SPO_DEVISE_A(+) = 14
   AND SPO_DEVISE_B(+) = ROO_DEVISE_ID;

1680 rows selected.

Elapsed: 00:00:01.01

SQL> select * from table(dbms_xplan.display_cursor(null,null,'iostats last'));

SQL_ID  7y1fqw64vu4xv, child number 0
-------------------------------------


Plan hash value: 593715089

----------------------------------------------------------------------------------------------------------------------
| Id  | Operation                      | Name                      | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
----------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT               |                           |      1 |        |   1680 |00:00:00.33 |   10993 |
|   1 |  NESTED LOOPS OUTER            |                           |      1 |    127 |   1680 |00:00:00.33 |   10993 |
|*  2 |   HASH JOIN OUTER              |                           |      1 |     97 |   1680 |00:00:00.01 |    3406 |
|   3 |    NESTED LOOPS                |                           |      1 |     97 |   1680 |00:00:00.01 |    3400 |
|*  4 |     TABLE ACCESS BY INDEX ROWID| MUT_SOUS_JACENT           |      1 |     97 |   1680 |00:00:00.01 |      38 |
|*  5 |      INDEX RANGE SCAN          | IDX_SOUS_JACENT_PARENT_ID |      1 |    101 |   1791 |00:00:00.01 |       6 |
|   6 |     TABLE ACCESS BY INDEX ROWID| MUT_ROOT2                 |   1680 |      1 |   1680 |00:00:00.01 |    3362 |
|*  7 |      INDEX UNIQUE SCAN         | PK_ROOT2                  |   1680 |      1 |   1680 |00:00:00.01 |    1682 |
|   8 |    TABLE ACCESS BY INDEX ROWID | SPOT                      |      1 |      8 |     21 |00:00:00.01 |       6 |
|*  9 |     INDEX RANGE SCAN           | PK_SPOT                   |      1 |      8 |     21 |00:00:00.01 |       4 |
|  10 |   TABLE ACCESS BY INDEX ROWID  | MUT_HISTO_ROOT            |   1680 |      1 |   1563 |00:00:00.31 |    7587 |
|* 11 |    INDEX RANGE SCAN            | IDX_MHR_LOHTHTLD          |   1680 |      1 |   1563 |00:00:00.29 |    6024 |
----------------------------------------------------------------------------------------------------------------------

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

   2 - access("SPO_DEVISE_B"="ROO_DEVISE_ID")
   4 - filter(("SJA_STARTDATE"<=TO_DATE(:SYS_B_01,:SYS_B_02) AND
              ("SJA_STOPDATE">=TO_DATE(:SYS_B_03,:SYS_B_04) OR "SJA_STOPDATE" IS NULL)))
   5 - access("SJA_PARENT_ID"=:SYS_B_00)
   7 - access("ROO_ID"="SJA_ROOTID_SJ")
   9 - access("SPOT"."LYX_DAY"=TO_DATE(:SYS_B_09,:SYS_B_10) AND "SPO_DEVISE_A"=:SYS_B_11)
  11 - access("SJA_ROOTID_SJ"="HISTO"."LYX_OWNER_ID" AND "HIR_TIMETYPE_ID"=:SYS_B_08 AND
              "HIR_TYPE_ID"=:SYS_B_07)
       filter(TRUNC(INTERNAL_FUNCTION("HISTO"."LYX_DAY"))=TO_DATE(:SYS_B_05,:SYS_B_06))
La requête a généré seulement 10K logical reads au lieu de 4752K lorsqu'on avait la scalar subquery.
Maintenant qu'on a isolé le problème on peut regarder de plus près comment améliorer l'accès à la table MUT_STATUS_VALOSIMPLE sans passer par un INDEX SKIP SCAN.
Collectons d'abord quelques informations sur les index existants pour cette table:
Index Name                           Pos# Order Column Name
------------------------------ ---------- ----- ------------------------------
idx_obj_date                            1 ASC   stv_date
                                        2 ASC   stv_obj_id

pk_valosimple                           1 ASC   stv_status_id

 L'index utilisé via l'opération SKIP SCAN est l'index IDX_OBJ_DATE. Cet index est en fait un index composite sur les colonnes STV_DATE et STV_OBJ_ID.
La requête utilise un prédicat sur STV_OBJ_ID qui correspond à la deuxième colonne de l'index. D'où un accès en INDEX SKIP SCAN beaucoup moins efficace qu'un INDEX RANGE SCAN.

 Etape 4: Trouver une solution

Une fois le problème identifié et la cause du problème isolé, cette étape consiste à trouver une solution à la cause du problème qui puisse être implémentable.
Dans notre exemple cette étape va consister à trouver un moyen d'optimiser l'accès à la table MUT_STATUS_VALOSIMPLE.
Crééons un index sur la colonne  STV_OBJ_ID uniquement et voyons ce que donne la requête lorsqu'on l'exécute:
 create index IDX_STV_OBJ_ID on MUT_STATUS_VALOSIMPLE(STV_OBJ_ID);

Plan hash value: 1150780941

-----------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                          | Name                      | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |
-----------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                   |                           |      1 |        |   1680 |00:00:00.38 |    9320 |      0 |
|   1 |  NESTED LOOPS                      |                           |   1680 |      1 |   1680 |00:00:00.65 |   45714 |     37 |
|   2 |   NESTED LOOPS                     |                           |   1680 |      1 |   1782 |00:00:00.61 |   40255 |     37 |
|   3 |    TABLE ACCESS BY INDEX ROWID     | MUT_STATUS_VALOSIMPLE     |   1680 |      1 |   1782 |00:00:00.59 |   36578 |     37 |
|*  4 |     INDEX RANGE SCAN               | IDX_OBJ_DATE              |   1680 |      1 |   1782 |00:00:00.56 |   34832 |     37 |
|   5 |      SORT AGGREGATE                |                           |   1680 |      1 |   1680 |00:00:00.52 |   31355 |     37 |
|   6 |       NESTED LOOPS                 |                           |   1680 |    519 |   4351 |00:00:00.51 |   31355 |     37 |
|   7 |        NESTED LOOPS                |                           |   1680 |    518 |   4623 |00:00:00.39 |   17373 |     36 |
|*  8 |         TABLE ACCESS BY INDEX ROWID| MUT_STATUS_VALOSIMPLE     |   1680 |    518 |   4623 |00:00:00.33 |    8014 |     36 |
|*  9 |          INDEX RANGE SCAN          | IDX_STV_OBJ_ID            |   1680 |    518 |   4623 |00:00:00.28 |    3485 |     36 |
|* 10 |         INDEX UNIQUE SCAN          | PK_POND                   |   4623 |      1 |   4623 |00:00:00.05 |    9359 |      0 |
|* 11 |        TABLE ACCESS BY INDEX ROWID | MUTATION                  |   4623 |      1 |   4351 |00:00:00.10 |   13982 |      1 |
|* 12 |         INDEX UNIQUE SCAN          | PK_MUTATION               |   4623 |      1 |   4623 |00:00:00.07 |    9359 |      1 |
|* 13 |    INDEX UNIQUE SCAN               | PK_POND                   |   1782 |      1 |   1782 |00:00:00.02 |    3677 |      0 |
|* 14 |   TABLE ACCESS BY INDEX ROWID      | MUTATION                  |   1782 |      1 |   1680 |00:00:00.03 |    5459 |      0 |
|* 15 |    INDEX UNIQUE SCAN               | PK_MUTATION               |   1782 |      1 |   1782 |00:00:00.02 |    3677 |      0 |
|  16 |  NESTED LOOPS OUTER                |                           |      1 |     86 |   1680 |00:00:00.38 |    9320 |      0 |
|* 17 |   HASH JOIN OUTER                  |                           |      1 |     81 |   1680 |00:00:00.04 |    3406 |      0 |
|  18 |    NESTED LOOPS                    |                           |      1 |     81 |   1680 |00:00:00.04 |    3400 |      0 |
|* 19 |     TABLE ACCESS BY INDEX ROWID    | MUT_SOUS_JACENT           |      1 |     81 |   1680 |00:00:00.01 |      38 |      0 |
|* 20 |      INDEX RANGE SCAN              | IDX_SOUS_JACENT_PARENT_ID |      1 |     85 |   1791 |00:00:00.01 |       6 |      0 |
|  21 |     TABLE ACCESS BY INDEX ROWID    | MUT_ROOT2                 |   1680 |      1 |   1680 |00:00:00.02 |    3362 |      0 |
|* 22 |      INDEX UNIQUE SCAN             | PK_ROOT2                  |   1680 |      1 |   1680 |00:00:00.01 |    1682 |      0 |
|  23 |    TABLE ACCESS BY INDEX ROWID     | SPOT                      |      1 |      7 |     21 |00:00:00.01 |       6 |      0 |
|* 24 |     INDEX RANGE SCAN               | PK_SPOT                   |      1 |      7 |     21 |00:00:00.01 |       4 |      0 |
|  25 |   TABLE ACCESS BY INDEX ROWID      | MUT_HISTO_ROOT            |   1680 |      1 |      0 |00:00:00.33 |    5914 |      0 |
|* 26 |    INDEX RANGE SCAN                | IDX_MHR_LOHTHTLD          |   1680 |      1 |      0 |00:00:00.33 |    5914 |      0 |
-----------------------------------------------------------------------------------------------------------------------------------

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

   4 - access("STV_DATE"= AND "STV_OBJ_ID"=:B1)
   8 - filter("STV_DATE"<=TO_DATE(:SYS_B_00,:SYS_B_01))
   9 - access("STV_OBJ_ID"=:B1)
  10 - access("STV_STATUS_ID"="PON_STATUS_ID")
  11 - filter(("MUT_TYPESTATUS_ID"=:SYS_B_02 AND "MUT_LASTFLAG"=:SYS_B_03))
  12 - access("MUT_ID"="STV_STATUS_ID")
  13 - access("STV_STATUS_ID"="PON_STATUS_ID")
  14 - filter(("MUT_TYPESTATUS_ID"=:SYS_B_04 AND "MUT_LASTFLAG"=:SYS_B_05))
  15 - access("MUT_ID"="STV_STATUS_ID")
  17 - access("SPO_DEVISE_B"="ROO_DEVISE_ID")
  19 - filter(("SJA_STARTDATE"<=TO_DATE(:SYS_B_07,:SYS_B_08) AND ("SJA_STOPDATE">=TO_DATE(:SYS_B_09,:SYS_B_10) OR
              "SJA_STOPDATE" IS NULL)))
  20 - access("SJA_PARENT_ID"=:SYS_B_06)
  22 - access("ROO_ID"="SJA_ROOTID_SJ")
  24 - access("SPOT"."LYX_DAY"=TO_DATE(:SYS_B_15,:SYS_B_16) AND "SPO_DEVISE_A"=:SYS_B_17)
  26 - access("SJA_ROOTID_SJ"="HISTO"."LYX_OWNER_ID" AND "HIR_TIMETYPE_ID"=:SYS_B_14 AND "HIR_TYPE_ID"=:SYS_B_13)
       filter(TRUNC(INTERNAL_FUNCTION("HISTO"."LYX_DAY"))=TO_DATE(:SYS_B_11,:SYS_B_12))
La requête ne génère plus que 45K logical reads et on a bien un INDEX RANGE SCAN sur notre nouvel index à l'opération 9.
On peut noter aussi que des tables sont accédées 2 fois à cause la subquery retournant le MAX(STV_DATE). On peut éviter ce double accès sur ces tables en utilisant une requête analytique:
 Select HIR_MTM,
 ROO_ID,
 sja_fieldid FIELDID,
 (select STV_VALUE from
 (select STV_VALUE,STV_DATE,STV_OBJ_ID,max(STV_DATE) over (partition by STV_OBJ_ID) THE_MAX
 From MUT_STATUS_VALOSIMPLE,
 MUT_STATUS_PONDERATION,
 MUTATION
 Where STV_DATE <= TO_DATE('29-06-2012', 'dd-mm-yyyy')
 And STV_STATUS_ID = PON_STATUS_ID
 And MUT_ID = STV_STATUS_ID
 And MUT_TYPESTATUS_ID = 2
 And MUT_LASTFLAG = 1) v
 where v.STV_DATE=v.THE_MAX and v.STV_OBJ_ID=SJA_ID) POND,
 SPO_SPOT
From MUT_HISTO_ROOT histo, MUT_SOUS_JACENT, MUT_ROOT2, SPOT
 Where SJA_PARENT_ID = 164826982
 And SJA_STARTDATE <= TO_DATE('29-06-2012', 'dd-mm-yyyy')
 And (SJA_STOPDATE >= TO_DATE('29-06-2012', 'dd-mm-yyyy') or
 SJA_STOPDATE is NULL)
 And TRUNC(histo.LYX_DAY(+)) = TO_DATE('29-06-2012', 'dd-mm-yyyy')
 And SJA_ROOTID_SJ = histo.LYX_OWNER_ID(+)
 And HIR_TYPE_ID(+) = 50000
 And HIR_TIMETYPE_ID(+) = 40001
 And ROO_ID = SJA_ROOTID_SJ
 AND SPOT.LYX_DAY(+) = TO_DATE('29-06-2012', 'dd-mm-yyyy')
 AND SPO_DEVISE_A(+) = 14
 AND SPO_DEVISE_B(+) = ROO_DEVISE_ID;

Plan hash value: 1110971357

-----------------------------------------------------------------------------------------------------------------------
| Id  | Operation                       | Name                      | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-----------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                |                           |      1 |        |   1680 |00:00:00.34 |    9320 |
|*  1 |  VIEW                           |                           |   1680 |    519 |   1680 |00:00:00.32 |   31355 |
|   2 |   WINDOW BUFFER                 |                           |   1680 |    519 |   4351 |00:00:00.31 |   31355 |
|   3 |    NESTED LOOPS                 |                           |   1680 |    519 |   4351 |00:00:00.25 |   31355 |
|   4 |     NESTED LOOPS                |                           |   1680 |    518 |   4623 |00:00:00.14 |   17373 |
|*  5 |      TABLE ACCESS BY INDEX ROWID| MUT_STATUS_VALOSIMPLE     |   1680 |    518 |   4623 |00:00:00.08 |    8014 |
|*  6 |       INDEX RANGE SCAN          | IDX_STV_OBJ_ID            |   1680 |    518 |   4623 |00:00:00.03 |    3485 |
|*  7 |      INDEX UNIQUE SCAN          | PK_POND                   |   4623 |      1 |   4623 |00:00:00.05 |    9359 |
|*  8 |     TABLE ACCESS BY INDEX ROWID | MUTATION                  |   4623 |      1 |   4351 |00:00:00.09 |   13982 |
|*  9 |      INDEX UNIQUE SCAN          | PK_MUTATION               |   4623 |      1 |   4623 |00:00:00.06 |    9359 |
|  10 |  NESTED LOOPS OUTER             |                           |      1 |     86 |   1680 |00:00:00.34 |    9320 |
|* 11 |   HASH JOIN OUTER               |                           |      1 |     81 |   1680 |00:00:00.02 |    3406 |
|  12 |    NESTED LOOPS                 |                           |      1 |     81 |   1680 |00:00:00.02 |    3400 |
|* 13 |     TABLE ACCESS BY INDEX ROWID | MUT_SOUS_JACENT           |      1 |     81 |   1680 |00:00:00.01 |      38 |
|* 14 |      INDEX RANGE SCAN           | IDX_SOUS_JACENT_PARENT_ID |      1 |     85 |   1791 |00:00:00.01 |       6 |
|  15 |     TABLE ACCESS BY INDEX ROWID | MUT_ROOT2                 |   1680 |      1 |   1680 |00:00:00.01 |    3362 |
|* 16 |      INDEX UNIQUE SCAN          | PK_ROOT2                  |   1680 |      1 |   1680 |00:00:00.01 |    1682 |
|  17 |    TABLE ACCESS BY INDEX ROWID  | SPOT                      |      1 |      7 |     21 |00:00:00.01 |       6 |
|* 18 |     INDEX RANGE SCAN            | PK_SPOT                   |      1 |      7 |     21 |00:00:00.01 |       4 |
|  19 |   TABLE ACCESS BY INDEX ROWID   | MUT_HISTO_ROOT            |   1680 |      1 |      0 |00:00:00.32 |    5914 |
|* 20 |    INDEX RANGE SCAN             | IDX_MHR_LOHTHTLD          |   1680 |      1 |      0 |00:00:00.31 |    5914 |
-----------------------------------------------------------------------------------------------------------------------

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

   1 - filter("V"."STV_DATE"="V"."THE_MAX")
   5 - filter("STV_DATE"<=TO_DATE(:SYS_B_00,:SYS_B_01))
   6 - access("STV_OBJ_ID"=:B1)
   7 - access("STV_STATUS_ID"="PON_STATUS_ID")
   8 - filter(("MUT_TYPESTATUS_ID"=:SYS_B_02 AND "MUT_LASTFLAG"=:SYS_B_03))
   9 - access("MUT_ID"="STV_STATUS_ID")
  11 - access("SPO_DEVISE_B"="ROO_DEVISE_ID")
  13 - filter(("SJA_STARTDATE"<=TO_DATE(:SYS_B_05,:SYS_B_06) AND ("SJA_STOPDATE">=TO_DATE(:SYS_B_07,:SYS_B_08)
              OR "SJA_STOPDATE" IS NULL)))
  14 - access("SJA_PARENT_ID"=:SYS_B_04)
  16 - access("ROO_ID"="SJA_ROOTID_SJ")
  18 - access("SPOT"."LYX_DAY"=TO_DATE(:SYS_B_13,:SYS_B_14) AND "SPO_DEVISE_A"=:SYS_B_15)
  20 - access("SJA_ROOTID_SJ"="HISTO"."LYX_OWNER_ID" AND "HIR_TIMETYPE_ID"=:SYS_B_12 AND
              "HIR_TYPE_ID"=:SYS_B_11)
       filter(TRUNC(INTERNAL_FUNCTION("HISTO"."LYX_DAY"))=TO_DATE(:SYS_B_09,:SYS_B_10))
 Cette réecriture de la requête n'entraine plus qu'un seul accès aux tables MUT_STATUS_VALOSIMPLE, MUT_STATUS_PONDERATION et MUTATION.
Et le nombre de logical reads n'est plus que de 31K.


Etape 5: Implementer la solution

Cette étape consiste à implémenter la solution de manière contrôlée afin de s'assurer que le problème est bien résolu et que des regressions ne sont pas notées.
Dans notre exemple cette étape a consisté à voir avec le chef de projet si l'index pouvait être crée directement en prod en tant que patch ou bien s'il était préférable d'attendre d'effectuer une batterie de tests supplémentaires.
Vu la criticité du problème la création de l'index en prod avait été décidé ce qui a conduit à une nette amélioration du process applicatif. Par contre, la réecriture de la requête avait été laissée à plus tard lors d'une livraison applicative.
Enfin, lors de cette étape on tente de quantifier l'amélioration apportée pour remonter l'information aux managers et recevoir en retour des compliments méritées RIEN.

mardi 9 avril 2013

DBLink et ORA-12154

Si vous tombez sur ce lien après une recherche sur google il est fort probable que avez eu affaire au même problème que moi.
SQL> create public database link MOX_SOXS12.WORLD
  2    connect to MOX$OWNER identified by moxowner
  3    using 'OPARSOXS12';

Database link created.

SQL> desc mox_change@MOX_SOXS12.WORLD
ERROR:
ORA-12154: TNS:could not resolve the connect identifier specified
Après avoir crée un DB link pointant sur une base dont l'alias est OPARSOXS12 je me suis retrouvé dans l'incapacité d'accéder aux données de ma base distante. Il semble que l'alias OPARSOXS12 ne puisse être résolu.
Un tnsping sur cet alias montre pourtant que la résolution s'effectue correctement:
C:\>tnsping oparsoxs12

TNS Ping Utility for 32-bit Windows: Version 11.2.0.1.0 - Production on 09-APR-2013 15:08:06

Copyright (c) 1997, 2010, Oracle.  All rights reserved.

Used parameter files:
C:\oracle\ora11.2\network\admin\sqlnet.ora

Used TNSNAMES adapter to resolve the alias
Attempting to contact (DESCRIPTION = (ADDRESS_LIST = (ADDRESS = (PROTOCOL = TCP) (Host = SOXDBGDB01.fr.world.socgen) (Port = 1524))) (CONNECT_DATA = (SID = SOXS12)))
OK (80 msec)

Jettons un oeil dans mon TNSNAMES.ora:
IFILE =S:\_Tools\ora11201\network\admin\tnsnames.ora 

Mon TNSNAMES.ora pointe en fait sur un autre fichier tnsnames grâce à la clause IFILE.
L'alias marche très bien lorsqu'on se connecte via SqlPlus mais ça a l'air de poser problème lorsqu'on utilise un DBLink.

Essayons de mettre directement les informations dans le TNSNAMES.ORA du client (la base où se trouve le dblink que j'ai crée):
IFILE =S:\_Tools\ora11201\network\admin\tnsnames.ora
### MACHINE
OPARSOXS12.WORLD =
        (DESCRIPTION =
                (ADDRESS_LIST =
                        (ADDRESS =
                                (PROTOCOL = TCP)
                                (Host = SOXDBGDB01.fr.world.socgen)
                                (Port = 1524)
                        )
                )
                (CONNECT_DATA =
                        (SID = SOXS12)
                )
        )
Maintenant mon DB link fonctionne correctement:
SQL> desc mox_change@MOX_SOXS12.WORLD
 Name

                                                                                                                                   Null?    Type
 ---------------------------------------------------------------------------------------------------------------------------------------------------------------
----------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------- -----
--- ------------------------------------------------------------------------------------------------------------------------------------------------------------
----------------------------------------------------------------------------------------------------------------------------------------------------------------

 ID

                                                                                                                                   NOT NULL NUMBER
 JOB_ID

                                                                                                                                            NUMBER
 CHANGETYPE_ID

                                                                                                                                   NOT NULL NUMBER
 CHANGE_USER

                                                                                                                                   NOT NULL VARCHAR2(200)
 CHANGE_DATE

                                                                                                                                   NOT NULL DATE
 CHANGE_COMMENT

                                                                                                                                   NOT NULL VARCHAR2(2000)
En faisant une petite recherche sur google je suis tombé sur la page suivante du site AskTom:
http://asktom.oracle.com/pls/asktom/f?p=100:11:0::::P11_QUESTION_ID:489021635775

Tom Kyte y dit que la clause IFILE n'est en fait pas supporté pour les fichiers de configuration Oracle Net (*.ORA). A la date où Tom Kyte a écrit ces mots il s'agissait de la version 8i.
La note MOS 1339269.1 semble indiquer qu'en 10g ça n'était toujours pas supporté:
ifiles are not officially supported with Oracle Net admin files
Enhancement request Bug 12676140  Would Like the Use of ifiles to be officially supported for net, is currently outstanding.

Si on effectue une recherche sur la doc Oracle 11g R2 on s'aperçoit que la clause IFILE n'est décrite que pour les fichier de paramétrage d'instance (init.ora).