Plans d'exécutions différents suivant la source

Version imprimable

08/07/2009, 09h55
jmerigea

Plans d'exécutions différents suivant la source

Bonjour,

Je rencontre actuellement le soucis suivant:

Lorsque mon programme effectue une requete en bdd (via JDBC et OraclePreparedStatement avec bind variable), celle-ci s'effectue en moyenne en ~500ms. Ensuite, via sqldeveloper, je récupère cette requete dans la vue v$sql, puis je l'exécute (dans sqldeveloper). Celle-ci s'accomplie en moyenne en ~5-10ms.
Une nouvelle ligne est apparue dans v$sql (la colonne EXECUTION de la première n'a pas augmenté). Le sql est bien le meme, à l'espace près. De plus, la colonne SQL_ID est bien la meme pour les deux lignes, mais le ELAPSED_TIME/EXECUTION est très différent.

Lorsque je regarde la vue v$sql_plan, je vois deux plans d'exécutions différents corespondant au meme SQL_ID.

Afin de solutionner ce problème j'ai donc ajouté des hints dans mon programme, afin de forcer Oracle à utiliser le plan d'exécution qu'il calcule sous sqldeveloper, et j'obtiens le gain attendu.

Cependant, j'avoue ne pas comprendre d'où provient cette différence. Peut-etre du OraclePreparedStatement? Du fait que l'appli se connecte à travers un pool de connexions (je vois pas pourquoi, mais bon...)?

Ca m'inquiete un peu, car il y a d'autres requetes qui sont impactées, et j'aimerai donc comprendre d'où cela vient !

Merci d'avance.

PS: stats complètes calculées..
08/07/2009, 11h12
pifor

Quelle est la version Oracle utilisée à 4 chiffres ?

Essayez d'utiliser V$SQL_SHARED_CURSOR pour savoir pourquoi les curseurs ne sont pas partagés.
08/07/2009, 11h43
NGasparotto

Est-ce le meme user qui est utilise dans les deux cas ? Est-il possible qu'il y ait un trigger on logon declenche dans un cas pas dans l'autre ?
La requete utilise-t'elle des bind variables ? Des valeurs litterales ? Quelle est la valeur de CURSOR_SHARING ?
(et bien sur sans oublier la version comme l'a demande Pierre).

Nicolas.
08/07/2009, 12h34
jmerigea

La version utilisée est : Oracle Database 11g Enterprise Edition Release 11.1.0.6.0 - Production (dans v$version).

C'est bien le meme user dans les deux cas, et il n'y a pas de trigger on loggon.

Il y a des valeurs litérales dans un decode, mais ce sont toujours les memes.

Par contre il y a bien des bind variables. Dans la vue v$sql_shared_cursor, en sélectionnant à partir du sql_id de la requete, j'obtiens deux lignes avec le meme sql_id. L'un des curseurs a un fils, l'autre a le paramètre USER_BIND_PEEK_MISMATCH à Y. D'après la doc: "Cursor is not shared because value of one or more user binds is different and this has a potential to change the execution plan".

Le paramètre CURSOR_SHARING a pour valeur EXACT.

Il semblerait donc qu'il n'utilise pas le meme curseur à cause des bind variables, qui pouraient entrainer une modif du plan d'exécution.
Pourtant, lorsque je modifie la valeur de la bind variable sous sqldeveloper, il garde bien le meme plan d'exécution (le plus optimisé), quand je modifie la valeur de la bind variable dans l'appli, il garde aussi le meme plan (le mauvais si je n'ai pas mis de hint). De plus, il me semblait que c'était tout l'intéret des bind variables, de réutiliser le meme plan avec des valeurs différentes. J'avoue etre un peu perdu ...
08/07/2009, 12h47
NGasparotto

Combien de lignes sont ramenees ? Tu as fais une trace+tkprof dans un cas comme dans l'autre ?

Citation:

Envoyé par jmerigea

Lorsque mon programme effectue une requete en bdd (via JDBC et OraclePreparedStatement avec bind variable), celle-ci s'effectue en moyenne en ~500ms...

Comment mesures-tu ce temps de reponse ? Du point de vue du client ou du serveur ?

Citation:

Envoyé par jmerigea

Ensuite, via sqldeveloper, je récupère cette requete dans la vue v$sql, puis je l'exécute (dans sqldeveloper). Celle-ci s'accomplie en moyenne en ~5-10ms.

Comment mesures-tu ce temps de reponse ? Est-ce pour ramener toutes les lignes, ou juste les premieres ?

Citation:

Envoyé par jmerigea

Afin de solutionner ce problème j'ai donc ajouté des hints dans mon programme

D'accord, tu as 500ms d'un cote, 50ms de l'autre, c'est 10 fois mieux, mais he, on parle d'un temps de depart d'une demi-seconde, est-ce que ca vaut vraiment le coup de :
1. perdre du temps pour faire du tuning ?
2. figer le plan d'execution ?

Nicolas.
08/07/2009, 14h04
jmerigea

La requete me ramène 5 lignes, mode ALL_ROW. En regardant les traces, je ne trouve pas plus indices.

Je mesure le temps de réponse en me basant sur la colonne ELAPSED divisé par la colonne EXECUTION de la vue v$sql. Je sais que ce n'est pas une méthode de mesure très "valide", mais j'obtiens des temps cohérents avec les logs de l'appli. Le fait de passer de 500ms à 5ms change beaucoup, car cette requete est utilisée plusieurs fois pour obtenir un résultat de l'appli (un moteur de recherche). En figeant le plan de cette manière, j'obtiens pas mal de mes résultats de recherche en 0.3s au lieu de 1.3s (environ) puisqu'elle était utilisée deux fois. Donc assez interessant ;)

J'en serais bien resté là, mais pour certaines recherches différentes, la requete de l'appli en bd dure 50s (ce qui laisse le temps d'aller se servir tranquilement un café ^^). Lorsque j'exécute sous sqldeveloper la requete à la bd, elle s'effectue en environ 5s (il reste de l'optimisation à faire, mais c'est déjà mieux). Et là je ne peux pas forcer le plan facilement, car la requete SQL est générée 'dynamiquement' au niveau de l'appli, en fonction des termes recherchés.

Et puis j'aime bien me creuser la tete et savoir pourquoi ca marche (ou pas ^^). D'autant que je suis vraiment étonné d'avoir des résultats 'completements' différents juste en changeant de client :-/
08/07/2009, 14h36
NGasparotto

Il serait tout de meme plus raisonnable de travailler sur des trace files, au moins pour savoir ou tu perds du temps, dans l'execution propre de la requete ? Dans le fetch ? Par rapport a ce que tu decris, peut-etre dans ce dernier, ca peut etre dependant de ton code utilise, mais avec JDBC, il y a des arrays pour gerer la taille des fetchs entre client et serveur. C'est juste une piste, mais des tracce sql pourraient en dire plus.

Nicolas.

En effet les traces de la deuxième requete précise bien que la perte de temps vient du fetch.

Voici la trace et le plan d'exécution pour la requete réalisée par l'appli:

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
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.01       0.01          0          0          0           0
Fetch     2499     54.26      54.33     642325   10516579          0       24987
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     2501     54.27      54.34     642325   10516579          0       24987
 
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: FIRST_ROWS
Parsing user id: 88  
 
Rows     Row Source Operation
-------  ---------------------------------------------------
  24987  SORT ORDER BY (cr=10516579 pr=642325 pw=642325 time=271 us cost=251784 size=2277385 card=48455)
  24987   NESTED LOOPS  (cr=10516579 pr=642325 pw=642325 time=5964 us)
  42712    NESTED LOOPS  (cr=10473013 pr=630637 pw=630637 time=2911 us cost=251212 size=2277385 card=48455)
  30685     VIEW  (cr=10442226 pr=630486 pw=630486 time=666 us cost=29395 size=2588784 card=78448)
  30685      HASH GROUP BY (cr=10442226 pr=630486 pw=630486 time=295 us cost=29395 size=1019824 card=78448)
  42824       VIEW  (cr=10442226 pr=630486 pw=630486 time=675 us cost=29395 size=1442246 card=110942)
  42824        HASH UNIQUE (cr=10442226 pr=630486 pw=630486 time=275 us cost=29395 size=8875360 card=110942)
1268880         HASH JOIN  (cr=10442226 pr=630486 pw=630486 time=260722 us cost=26522 size=18723120 card=234039)
 181270          TABLE ACCESS BY INDEX ROWID TB_DESCRIPTEUR_ATTRIBUT (cr=2013 pr=2012 pw=2012 time=3488 us cost=319 size=608640 card=15216)
 181270           INDEX RANGE SCAN I_OPT_DAT_TA (cr=687 pr=686 pw=686 time=1259 us cost=74 size=0 card=19134)(object id 71071)
10898171          TABLE ACCESS BY INDEX ROWID TB_DESCRIPTEUR_IG_FIC_EXPL (cr=10440213 pr=628474 pw=628474 time=346610 us cost=26199 size=21796360 card=544909)
10898171           INDEX RANGE SCAN I_OPT_IG_FIC_EXPL_2 (cr=49441 pr=49441 pw=49441 time=95354 us cost=453 size=0 card=98300)(object id 71132)
  42712     INDEX RANGE SCAN I_OPT_DC_FICHES (cr=30787 pr=151 pw=151 time=13452 us cost=1 size=0 card=1)(object id 71043)
  24987    TABLE ACCESS BY INDEX ROWID TB_DC_FICHES (cr=43566 pr=11688 pw=11688 time=0 us cost=3 size=14 card=1)

Et ceux pour la requete effectuée à partir d'un autre client:

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
 
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     1667      7.76       7.76      96558     171224          0       24987
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     1669      7.77       7.77      96558     171224          0       24987
 
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: FIRST_ROWS
Parsing user id: 88  
 
Rows     Row Source Operation
-------  ---------------------------------------------------
  24987  SORT ORDER BY (cr=171224 pr=96558 pw=96558 time=287 us cost=353004 size=2268690 card=48270)
  24987   NESTED LOOPS  (cr=171224 pr=96558 pw=96558 time=4679 us)
  42712    NESTED LOOPS  (cr=127752 pr=96558 pw=96558 time=2482 us cost=352433 size=2268690 card=48270)
  30685     VIEW  (cr=98138 pr=96558 pw=96558 time=644 us cost=130002 size=2595945 card=78665)
  30685      HASH GROUP BY (cr=98138 pr=96558 pw=96558 time=283 us cost=130002 size=1022645 card=78665)
  42824       VIEW  (cr=98138 pr=96558 pw=96558 time=684 us cost=130002 size=1446224 card=111248)
  42824        HASH UNIQUE (cr=98138 pr=96558 pw=96558 time=273 us cost=130002 size=8899840 card=111248)
1268880         HASH JOIN  (cr=98138 pr=96558 pw=96558 time=51071 us cost=54196 size=905598800 card=11319985)
 181270          TABLE ACCESS FULL TB_DESCRIPTEUR_ATTRIBUT (cr=1576 pr=0 pw=0 time=1193 us cost=433 size=5719360 card=142984)
10898171          TABLE ACCESS FULL TB_DESCRIPTEUR_IG_FIC_EXPL (cr=96562 pr=96558 pw=96558 time=68339 us cost=26464 size=435926840 card=10898171)
  42712     INDEX RANGE SCAN I_OPT_DC_FICHES (cr=29614 pr=0 pw=0 time=11998 us cost=1 size=0 card=1)(object id 71043)
  24987    TABLE ACCESS BY INDEX ROWID TB_DC_FICHES (cr=43472 pr=0 pw=0 time=0 us cost=3 size=14 card=1)

Je vais me renseigner sur la taille des fetch avec le JDBC, merci bien pour cette piste déjà :D

Edit: Après modif du paramètre fetchSize à 100, j'obtiens le résultat suivant:

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
 
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      250     53.25      53.28     578465   10516579          0       24987
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      252     53.25      53.28     578465   10516579          0       24987
 
Misses in library cache during parse: 0
Optimizer mode: FIRST_ROWS
Parsing user id: 88  
 
Rows     Row Source Operation
-------  ---------------------------------------------------
  24987  SORT ORDER BY (cr=10516579 pr=578465 pw=578465 time=240 us cost=251784 size=2277385 card=48455)
  24987   NESTED LOOPS  (cr=10516579 pr=578465 pw=578465 time=6065 us)
  42712    NESTED LOOPS  (cr=10473013 pr=566777 pw=566777 time=2919 us cost=251212 size=2277385 card=48455)
  30685     VIEW  (cr=10442226 pr=566626 pw=566626 time=683 us cost=29395 size=2588784 card=78448)
  30685      HASH GROUP BY (cr=10442226 pr=566626 pw=566626 time=311 us cost=29395 size=1019824 card=78448)
  42824       VIEW  (cr=10442226 pr=566626 pw=566626 time=686 us cost=29395 size=1442246 card=110942)
  42824        HASH UNIQUE (cr=10442226 pr=566626 pw=566626 time=277 us cost=29395 size=8875360 card=110942)
1268880         HASH JOIN  (cr=10442226 pr=566626 pw=566626 time=250941 us cost=26522 size=18723120 card=234039)
 181270          TABLE ACCESS BY INDEX ROWID TB_DESCRIPTEUR_ATTRIBUT (cr=2013 pr=2013 pw=2013 time=3524 us cost=319 size=608640 card=15216)
 181270           INDEX RANGE SCAN I_OPT_DAT_TA (cr=687 pr=687 pw=687 time=1258 us cost=74 size=0 card=19134)(object id 71071)
10898171          TABLE ACCESS BY INDEX ROWID TB_DESCRIPTEUR_IG_FIC_EXPL (cr=10440213 pr=564613 pw=564613 time=346418 us cost=26199 size=21796360 card=544909)
10898171           INDEX RANGE SCAN I_OPT_IG_FIC_EXPL_2 (cr=49441 pr=49440 pw=49440 time=94706 us cost=453 size=0 card=98300)(object id 71132)
  42712     INDEX RANGE SCAN I_OPT_DC_FICHES (cr=30787 pr=151 pw=151 time=13378 us cost=1 size=0 card=1)(object id 71043)
  24987    TABLE ACCESS BY INDEX ROWID TB_DC_FICHES (cr=43566 pr=11688 pw=11688 time=0 us cost=3 size=14 card=1)

Moins de fetch, mais toujours aussi long, et le moteur n'accède toujours pas aux données de la meme manière qu'avec sqldev ou sqlplus. :?

Ce que je n'explique pas c'est la difference d'explain plan, que les temps d'acces ou de retour (fetch) soient different, ok, mais l'utilisation ou non d'index ne soit pas pareil est plutot surprenant.
Je me pencherais plus particulierement sur les lignes la :
Code:

1 2 3 4 181270 TABLE ACCESS BY INDEX ROWID TB_DESCRIPTEUR_ATTRIBUT (cr=2013 pr=2012 pw=2012 time=3488 us cost=319 size=608640 card=15216) 181270 INDEX RANGE SCAN I_OPT_DAT_TA (cr=687 pr=686 pw=686 time=1259 us cost=74 size=0 card=19134)(object id 71071) 10898171 TABLE ACCESS BY INDEX ROWID TB_DESCRIPTEUR_IG_FIC_EXPL (cr=10440213 pr=628474 pw=628474 time=346610 us cost=26199 size=21796360 card=544909) 10898171 INDEX RANGE SCAN I_OPT_IG_FIC_EXPL_2 (cr=49441 pr=49441 pw=49441 time=95354 us cost=453 size=0 card=98300)(object id 71132)
Alors que depuis un autre client :
Code:

1 2 3 4 42824 HASH UNIQUE (cr=98138 pr=96558 pw=96558 time=273 us cost=130002 size=8899840 card=111248) 1268880 HASH JOIN (cr=98138 pr=96558 pw=96558 time=51071 us cost=54196 size=905598800 card=11319985) 181270 TABLE ACCESS FULL TB_DESCRIPTEUR_ATTRIBUT (cr=1576 pr=0 pw=0 time=1193 us cost=433 size=5719360 card=142984) 10898171 TABLE ACCESS FULL TB_DESCRIPTEUR_IG_FIC_EXPL (cr=96562 pr=96558 pw=96558 time=68339 us cost=26464 size=435926840 card=10898171)
Es-tu sur que la requete est bien la meme, et qu'elle est execute de la meme facon (avec bind variable des deux cotes, etc...).
Enfin, je ne connais pas ton code execute depuis le client a travers le JDBC, mais ca meriterait d'approffondir la question, notemment la declaration du/des curseur(s), la recuperation de donnees, etc.
Et aussi, attention a la version des differents clients utilises.
Tu as dit plut tot qu'il y avait un pool de connection, de quel type est-il ? Comment est-il defini ?

Nicolas.

10/07/2009, 14h26
jmerigea

Je viens de réaliser un petit test rapide avec un mini prog java reproduisant la requete et en modifiant la version du pilote ojdbc, et cela viendrait bien d'ici, puisque qu'avec les derniers la requete se réalise en 5s, et avec ceux utilisés par l'appli en 50s.

Merci beaucoup NGasparotto pour m'avoir sorti d'ici :ccool:

Il ne me reste plus qu'a mettre à jour l'appli pour utiliser les derniers drivers, et je pourrais commencer à travailler :D
10/07/2009, 15h14
NGasparotto

Citation:

Envoyé par jmerigea

Je viens de réaliser un petit test rapide avec un mini prog java reproduisant la requete et en modifiant la version du pilote ojdbc, et cela viendrait bien d'ici, puisque qu'avec les derniers la requete se réalise en 5s, et avec ceux utilisés par l'appli en 50s...

Plutot interessant...

Nicolas.
10/07/2009, 21h41
pachot

Bonjour,
Pour creuser le USER_BIND_PEEK_MISMATCH, il serait interressant de vérifier les types des variables dans V$SQL_BIND_METADATA
Cordialement,
Franck.