Discussion :

[bleporini]

Hello,

J'ai un problème assez gênant: suivant quel client interroge la base, le plan d'exécution pour une même requête est différent et du coup les temps de réponse s'en ressentent (cf les rapports tkprof suivants):

Avec SQLDevelopper:

Code :

Sélectionner tout - Visualiser dans une fenêtre à part

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
 
select to_char(p.TIME, 'DD/MM/YYYY HH24:MI:SS'), p.rfsi, p.name, p.ident,
  p.digital_input, p.digital_output, p.location_status, p.status,
  p.LOCATION.sdo_point.x, p.LOCATION.sdo_point.y
from
 AVL_HISTO_12H p WHERE  p.TIME = (SELECT MAX(o.TIME) FROM AVL_HISTO_12H o
  WHERE o.rfsi = p.rfsi  AND  sdo_filter ( o.LOCATION, mdsys.sdo_geometry
  (2003,8307,null, mdsys.sdo_elem_info_array(1,1003,1),
  mdsys.sdo_ordinate_array(-0.5687434055686004,43.70631327517212,
  -0.5650905420763318,43.70641123074462,-0.565174053106591,43.70805109390254,
  -0.5688270215156054,43.7079531353934,-0.5687434055686004,43.70631327517212))
  ,'querytype=WINDOW') = 'TRUE') AND  rownum <=501
 
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.09       0.09          0        822          0           0
Execute      1      0.01       0.01          0          6          2           0
Fetch        1      0.00       0.00          0          6          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.11       0.10          0        834          2           0
 
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 73
 
Rows     Row Source Operation
-------  ---------------------------------------------------
      0  COUNT STOPKEY (cr=209 pr=0 pw=0 time=673396 us)
      0   HASH JOIN  (cr=209 pr=0 pw=0 time=673376 us)
      0    VIEW  VW_SQ_1 (cr=209 pr=0 pw=0 time=673118 us)
      0     HASH GROUP BY (cr=209 pr=0 pw=0 time=673105 us)
      0      TABLE ACCESS BY INDEX ROWID AVL_HISTO_12H (cr=209 pr=0 pw=0 time=67
2901 us)
      0       DOMAIN INDEX  AVL_HISTO_12H_SIDX (cr=209 pr=0 pw=0 time=672878 us)
      0    TABLE ACCESS FULL AVL_HISTO_12H (cr=0 pr=0 pw=0 time=0 us)
 
********************************************************************************

... et avec l'appli j2ee:

Code :

Sélectionner tout - Visualiser dans une fenêtre à part

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
 
select to_char(p.TIME, 'DD/MM/YYYY HH24:MI:SS'), p.rfsi, p.name, p.ident,
  p.digital_input, p.digital_output, p.location_status, p.status,
  p.LOCATION.sdo_point.x, p.LOCATION.sdo_point.y
from
 AVL_HISTO_12H p WHERE  p.TIME = (SELECT MAX(o.TIME) FROM AVL_HISTO_12H o
  WHERE o.rfsi = p.rfsi  AND  sdo_filter ( o.LOCATION, mdsys.sdo_geometry
  (2003,8307,null, mdsys.sdo_elem_info_array(1,1003,1),
  mdsys.sdo_ordinate_array(-0.5687434055686004,43.70631327517212,
  -0.5650905420763318,43.70641123074462,-0.565174053106591,43.70805109390254,
  -0.5688270215156054,43.7079531353934,-0.5687434055686004,43.70631327517212))
  ,'querytype=WINDOW') = 'TRUE') AND  rownum <=501
 
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.04       0.04          0        495          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1     45.89      48.85          0       2580          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3     45.93      48.89          0       3075          0           0
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 73
 
Rows     Row Source Operation
-------  ---------------------------------------------------
      0  COUNT STOPKEY (cr=1306160 pr=0 pw=0 time=291420854 us)
      0   HASH JOIN  (cr=1306160 pr=0 pw=0 time=291420840 us)
      0    VIEW  VW_SQ_1 (cr=1306160 pr=0 pw=0 time=291420671 us)
      0     HASH GROUP BY (cr=1306160 pr=0 pw=0 time=291420661 us)
      0      TABLE ACCESS FULL AVL_HISTO_12H (cr=1306160 pr=0 pw=0 time=29142051
0 us)
      0    TABLE ACCESS FULL AVL_HISTO_12H (cr=0 pr=0 pw=0 time=0 us)
 
********************************************************************************

Dans un cas il apparaît clairement que l'index est utilisé alors que dans l'autre il y a un FTS et le nombre de blocs remontés explose.

Les deux requête portent évidemment sur le même jeu de donnée, la même instance, remonte les mêmes données, etc.

Dans les faits, cela correspond à une diff de perf de ~100ms contre ~226s!

L'expérience est parfaitement répétable et les attributions de plans sont constantes: toujours le mauvais pour l'appli et toujours le bon pour le client SQL.

Si quelqu'un a une piste...

[13thFloor]

C'est le même user qui exécute la requête ?
N'y a t-il pas un trigger ou un alter session qui positionne un paramètre qui pourrait altérer le plan d'exécution ? Je pencherai pour ce dernier cas.
Précision utile : version d'Oracle ?

[bleporini]

La version d'Oracle: 10.2.0.1.0

C'est effectivement le même user.

Il n'y a pas d'alter session, la requête est générée par Hibernate. Fait intéressant, le comportement est correct si l'appli exploite une autre instance.

L'investigation de ce problème m'a amené à rencontrer des comportement totalement inattendus avec cette instance, tels que l'impossibilité de collecter les statistiques (ORA-00979: not a GROUP BY expression en cours de collecte)... Il semble clairement que l'instance soit en cause et que le problème exposé ne soit qu'un des symptômes d'une santé globale plutôt précaire...

[fatsora]

Bonjour,

je te conseille de passer en 10.2.0.4 ...
la version 10.2.0.1 est trop "initiale"


as tu cursor_sharing=SIMILAR ou FORCE ?

[bleporini]

Pour le param:

Code :

Sélectionner tout - Visualiser dans une fenêtre à part

1
2
3
4
5
6
 
SQL> show parameter cursor_sharing
 
NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
cursor_sharing                       string      EXACT

Je note pour l'update, merci.

[13thFloor]

Un post de quelqu'un qui a sensiblement le même souci que toi : http://www.developpez.net/forums/d67...cle-hibernate/
Sauf que lui a repéré des attentes réseau mais a les mêmes symptômes : exécution sqlplus/toad correct, exécution via hibernate calamiteux.

Si une même requête a 2 plans d'exécution, c'est qu'il doit y avoir 2 sqlid en mémoire.