Requête paramétrisée plus lente que requête non paramétrisée [Résolu]

[Greybird]

Bonjour,

Je travaille sur Oracle 10.2.0.4.

Je rencontre aujourd'hui un souci qui me laisse perplexe, et je me tourne vers vous en quête d'une explication : une certaine requête non paramétrisée est extrèmement plus rapide que la même requête paramétrisée à laquelle on aurait passé les mêmes valeurs en paramètres. (1 seconde vs 1 minute)

Ci dessous les requêtes et leur plan d'exécution.

Code Requête paramétrisée :

1
2
3
4
5
6
7
 
SELECT   *
    FROM TTABLE
   WHERE 0 = 0
     AND dateSaisie >= :dateSaisie
     AND type = :type
ORDER BY idt DESC;

Code Plan d'exécution :

1
2
3
4
5
6
7
 
Operation                                Object Name     Rows     Bytes     Cost
 
SELECT STATEMENT Optimizer Mode=CHOOSE                    458               5611
  SORT ORDER BY                                           458       631 K   5611
    TABLE ACCESS BY INDEX ROWID     BDD$OWNER.TTABLE      458       631 K   5092
      INDEX RANGE SCAN     BDD$OWNER.ITTABLE3             8 K                 27

Code Requête non paramétrisée :

1
2
3
4
5
6
7
 
SELECT   *
    FROM TTABLE
   WHERE 0 = 0
     AND dateSaisie >= TO_DATE('03/09/2011 00:00:00', 'MM/DD/YYYY HH24:MI:SS')
     AND type = 'TYPE'
ORDER BY idt DESC;

Code Plan d'exécution :

1
2
3
4
5
6
7
 
Operation                                Object Name     Rows     Bytes     Cost
 
SELECT STATEMENT Optimizer Mode=CHOOSE                      1                  5
  SORT ORDER BY                                             1       1 K        5
    TABLE ACCESS BY INDEX ROWID     BDD$OWNER.TTABLE        1       1 K        4
      INDEX RANGE SCAN     BDD$OWNER.ITTABLE3               1                  3

S'agissant finalement du même plan, comment les coûts peuvent-il être aussi différents (moindre optimisation dans le cas de la requête paramétrisée du fait d'une moindre information ?) ?
Et surtout, pourquoi une telle différence de temps d'exécution au final ? Avez-vous des pistes pour résoudre ce souci ?

Merci d'avance,

Arnaud

[pachot]

Bonjour,
Sur le coût estimé, c'est normal puisque avec variable il estime que le prédicat correspond à 8000 entrées d'index alors qu'en conaissant la valeur (probablement la date qui est récente) c'est beaucoup moins.
Par contre le coût réel devrait être le même.
Peux-tu lancer la requête avec autotrace ou tkprof pour voir le nombre de blocs lus ? Le temps peut dépendre de ce qui est en cache.
Cordialement,
Franck.

[Greybird]

Bonjour et merci de ta réponse.

Notre DBA a fini par trouver le souci. Nous appelions ces requêtes depuis du code .NET, et nous bindions un objet de type .NET DateTime dans un paramètre de type DbType.DateTime.

Or DbType.DateTime correspond au type Oracle TimeStamp. Il fallait utiliser DbType.Date qui correspond au type Oracle Date.

Cette simple erreur causait le problème de performance indiqué.

Merci !

Arnaud

[mnitu]

Franchement je ne crois pas trop à votre solution. Déjà parce qu’un DBA qui fait tourner une base Oracle 10g en mode CHOOSE ce n’est pas un bon signe.

Je pense plutôt que vous avez être victime d’un phénomène de type introspection des valeurs des variables de liaison, « peek variable binding ». Une investigation plus approfondie pourrait vous éviter des mauvaises surprises dans l’avenir.

[Greybird]

Les paramètres passés avec ces paramètres ont permis de corriger la performance, suite à analyse par un de nos dba.
Je ne vois pas de raison de douter de son diagnostic en l'état.

En revanche, merci d'avoir porté ce phénomène de "peek variable binding", je vais étudier le cas et voir si il nous faut creuser plus loin.

Quand au fait que la base tourne en mode CHOOSE, je leur fait confiance sur la pertinence de ce choix, et d'ailleurs, je ne suis pas qualifié pour le critiquer. S'agissant d'une base critique énorme centralisant des traitements énormes et vieille de plus de 10 ans, avec des critères de disponibilité extrèmes, j'imagine que les changements de versions d'Oracle n'ont pas justifié la prise de risque amenée par un changement de configuration (mais là encore n'étant pas spécialiste, et mon problème de performance étant résolu).

[mnitu]

Bonjour,

Je vais essayer en quelques mots de vous donner « ma raison ».
Votre requête paramétrée existe déjà dans le shared pool. Le plan d’exécution qu’elle utilise a été déterminé par la valeur passé dans la variable de liaison (binding variable ou paramètre) au moment du "hard parsing" de la requête. A ce moment un curseur parent et un curseur fils à été crée et stockés dans le shared pool.

Quand vous avez changé le type de la variable de liaison en utilisant le DbType.Date le curseur parent est resté identique mais le nouveau type de la variable de liaison fait que le curseur fils ne peut plus être utilisé et donc un nouveau plan a été recherché en utilisant cette fois la nouvelle valeur de la variable de liaison. Ce qui à « résolu » en apparence votre problème de performance.

Jusqu’au là, dans votre cas, ces ne sont que des hypothèses. Mais, pour avancer je pense que vous pouvez faire un test assez simple. L’idée est de ré-exécuter 2 à 3 fois votre requête avec un variable de liaison de type DateTime (celle qui vous posée des soucis) et la valeur de votre exemple mais, en prenant soin de s ‘assurer que le hard parsing a lieu. Pour cella divers méthodes peuvent être employées comme par exemple la modification de la requête par l’ajout d’un alias de la table. Si votre DBA a raison le temps d’exécution de la requête doit reste désastreux : c’est le type de la variable qui pose problème, non ? Si non ou pourrait en discuter.

Bon courage!

[mnitu]

Churchil disait

Man will occasionally stumble over the truth, but most of the time he will pick himself up and continue on.

Pour examiner ce que se passe je vous propose le test suivant, en PL/SQL.
D'abord il y a eu création d'un index simple sur la colonne hire_date.
Ensuite deux blocs PL/SQL sont exécutés avec des variables de liaison de type différentes: date et timestamp mais, initialisés avec la même valeur.

Code :

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
 
C:\Users\Marius>sqlplus mni/mni
 
SQL*Plus: Release 11.2.0.1.0 Production ON Lun. Mars 14 20:09:26 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
 
mni@DIANA> SET serveroutput ON
mni@DIANA> declare
  2    l_dat  date := to_date('01/01/2007','DD/MM/YYYY');
  3    l_cpt     Pls_Integer;
  4  Begin
  5    SELECT /*+ gather_plan_statistics */
  6           count(*)
  7      INTO l_cpt
  8      FROM hr.employees look_for_me
  9     WHERE hire_date > l_dat;
 10    --
 11    dbms_output.put_line(l_cpt);
 12  End;
 13  /
30
 
Procédure PL/SQL terminée avec succès.
 
mni@DIANA> declare
  2    l_dat  Timestamp := to_timestamp('01/01/2007','DD/MM/YYYY');
  3    l_cpt     Pls_Integer;
  4  Begin
  5    SELECT /*+ gather_plan_statistics */
  6           count(*)
  7      INTO l_cpt
  8      FROM hr.employees look_for_me
  9     WHERE hire_date > l_dat;
 10    --
 11    dbms_output.put_line(l_cpt);
 12  End;
 13  /
30
 
Procédure PL/SQL terminée avec succès.

Voyons voire ce que se trouve dans le shared pool :

Code :

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
 
mni@DIANA> SELECT sql_id, child_number, sql_text, plan_hash_value
  2    FROM v$sql
  3   WHERE sql_text LIKE '%LOOK_FOR_ME%'
  4     AND sql_text NOT LIKE '%$%'
  5  /
 
SQL_ID        CHILD_NUMBER
------------- ------------
SQL_TEXT
----------------------------------------------------------------------------------------------------
PLAN_HASH_VALUE
---------------
64ty976tkvxn6            0
SELECT /*+ gather_plan_statistics */ COUNT(*) FROM HR.EMPLOYEES LOOK_FOR_ME WHERE HIRE_DATE > :B1
     2295068393
 
64ty976tkvxn6            1
SELECT /*+ gather_plan_statistics */ COUNT(*) FROM HR.EMPLOYEES LOOK_FOR_ME WHERE HIRE_DATE > :B1
     3089070950

Comme on s'attendait il y a le même sql_id parce que comme on disait, c'est le même texte donc, même curseur parent et deux curseur enfant 0 et 1 parce que le type de la variable de liaison a changé. Ça peut se confirmer par la requête qui suit:

Code :

1
2
3
4
5
6
7
8
9
10
 
mni@DIANA> SELECT child_number, bind_mismatch
  2    FROM v$sql_shared_cursor
  3   WHERE sql_id = '64ty976tkvxn6'
  4  /
 
CHILD_NUMBER B
------------ -
           0 N
           1 Y

Mais, si on examine attentivement la colonne plan_hash_value on pressente la mauvais surprise parce que la valeur n'est pas la même! Et ça veut dire que le plan d'exécution n'est probablement pas pas le même! Voyons voire

Code :

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
 
mni@DIANA> SET linesize 132
mni@DIANA> SELECT * FROM TABLE(dbms_xplan.display_cursor('64ty976tkvxn6',0,'ALLSTATS LAST'))
  2  /
 
PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
 
SQL_ID  64ty976tkvxn6, child number 0
-------------------------------------
SELECT /*+ gather_plan_statistics */ COUNT(*) FROM HR.EMPLOYEES
LOOK_FOR_ME WHERE HIRE_DATE > :B1
 
Plan hash value: 2295068393
 
-------------------------------------------------------------------------------------------
| Id  | Operation         | Name        | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |             |      1 |        |      1 |00:00:00.01 |       1 |
|   1 |  SORT AGGREGATE   |             |      1 |      1 |      1 |00:00:00.01 |       1 |
|*  2 |   INDEX RANGE SCAN| IX_EMPLOYEE |      1 |     19 |     30 |00:00:00.01 |       1 |
-------------------------------------------------------------------------------------------
 
Predicate Information (IDENTIFIED BY operation id):
---------------------------------------------------
 
   2 - access("HIRE_DATE">:B1)
 
 
20 ligne(s) sélectionnée(s).
 
mni@DIANA> SELECT * FROM TABLE(dbms_xplan.display_cursor('64ty976tkvxn6',1,'ALLSTATS LAST'))
  2  /
 
PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
 
SQL_ID  64ty976tkvxn6, child number 1
-------------------------------------
SELECT /*+ gather_plan_statistics */ COUNT(*) FROM HR.EMPLOYEES
LOOK_FOR_ME WHERE HIRE_DATE > :B1
 
Plan hash value: 3089070950
 
------------------------------------------------------------------------------------------
| Id  | Operation        | Name        | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT |             |      1 |        |      1 |00:00:00.01 |       1 |
|   1 |  SORT AGGREGATE  |             |      1 |      1 |      1 |00:00:00.01 |       1 |
|*  2 |   INDEX FULL SCAN| IX_EMPLOYEE |      1 |      5 |     30 |00:00:00.01 |       1 |
------------------------------------------------------------------------------------------
 
Predicate Information (IDENTIFIED BY operation id):
---------------------------------------------------
 
   2 - filter(INTERNAL_FUNCTION("HIRE_DATE")>:B1)
 
 
20 ligne(s) sélectionnée(s).

Et pouf, la claque. Dans le cas où la variable de liaison est de type timestamp l'index est utilisé en full scan, c'est-à-dire en mode balayage complet à cause de la fonction de conversion INTERNAL_FUNCTION. Merci à Oracle de ne pas bien documenter ces choses.

Et maintenant il n'y plus de mystère et toute le monde comprends pourquoi il y a des problèmes de performance dans ce cas.

A plus,
Marius NITU

[Ahmed AANGOUR]

Je confirme l'analyse de Mnitu. Vous êtes là face à un pb lié au Bind variable Peeking.
Le fait d'avoir changé le type de la variable a juste forcé un hard parse et donc un plan (approprié pour la date exécutée) a été trouvé. En ajoutant un simple espace dans la requête vous seriez arrivé au même résultat. Est-ce que pour autant vous en auriez conclu que l'espace permet de régler le pb de perf sur cette requête?
En tapant Bind Peeking sur Google vous trouverez un grand nombre d'articles sur le sujet (surtout en anglais).
j'ai essayé d'en écrire un en français il y'a quelques mois ici:
http://ahmedaangour.blogspot.com/201...e-peeking.html

J'espère que ça vous permettra d'y voir plus claire.

[Greybird]

Merci de vos précisions, j'ai d'ores et déjà remonté ce point du côté de notre équipe de dev et de dbas pour surveillance.

Nous suivons la chose, et aurons ce point à l'esprit en cas de souci.

Merci beaucoup pour votre aide!

[mnitu]

Envoyé par Ahmed AANGOUR

Je confirme l'analyse de Mnitu. Vous êtes là face à un pb lié au Bind variable Peeking.
...

Mon exemple démontre justement le contraire.
Ce n’est pas un problème de peek variable binding comme j'avais pensé au départ mais bien, un des cases ou le type de la variable de liaison (binding variable) influence le plan d’exécution.

[Ahmed AANGOUR]

ça m'apprendra à lire les posts en diagonale.

[Ahmed AANGOUR]

Le dernier article apparu sur le blog des développeurs du CBO Oracle m'a fait penser à cette discussion.
C'est exactement le même problème rencontré:
http://blogs.oracle.com/optimizer/en...t_from_sqlplus