requête qui rame avec MERGE JOIN CARTESIAN et LATCH cache buffer chains

Version imprimable

Bonjour,

Je travaille pour un éditeur de logiciel.
Un de nos clients (en 10g R2) a vu sa session bloquer sur la requête suivante:

Code:

SELECT 1 FROM DUAL WHERE EXISTS (SELECT 1 FROM VCHKCL X WHERE X.COMAR IN ('ICE') AND TRUNC(X.DATOP,'DD')<=TO_DATE('09062009','DDMMYYYY') AND TRUNC(X.DANEG,'DD')> TO_DATE('09062009','DDMMYYYY'))

VCHKCL est une vue. voici sa définition:

Code:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
 
CREATE OR REPLACE VIEW VCHKCL
(COMAR,NCOCL,NFICL,NUCON,NUFDP,DANEG,COINF,COINC,
 CNACT,CMECH,CAECH,CSOPT,MTSNA,QTCLO,COTSJ,DATOP,NUCPT,NUBIX,NUBCL)
AS 
SELECT 
M.COMAR,D.NUCON,D.NUFDP,M.NUCON,M.NUFDP,NVL(C.DAEOD,C.DATOP),N.COINF,D.COINC,
N.CNACT,N.CMECH,N.CAECH,N.CSOPT,N.MTSNA,M.QTCLO,A.COTSJ,NVL(N.DAEOD,N.DATOP),D.NUCPT,M.NUBIX,M.NUBCL
FROM 
MATCLO M,
FICDEP D,
FICNEG N,
FICNEG C,
NATACF A 
WHERE 
D.NUBIX=M.NUBCL AND 
D.NUFDP=M.NFICL AND 
N.NUBIX=M.NUBCL AND 
C.NUBIX=M.NUBIX AND 
A.CNACT=N.CNACT;

Les tables MATCLO, FICDEP et FICNEG sont partitionnées by range sur le champ COMAR.
La table NATACF n'est pas partitionnée.

En regardant dans v$session_wait j'ai vu que la session était bloquée sur l'évenement LATCH cache buffer chains.

Le plan d'execution de la requête est le suivant:

Code:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
 
Avant 
------------------------------------------------------------------------------------------------------------------ 
|   0 | SELECT STATEMENT                       |         |       |       |   339 (100)|          |       |       | 
|   1 |  FILTER                                |         |       |       |            |          |       |       | 
|   2 |   FAST DUAL                            |         |     1 |       |     2   (0)| 00:00:01 |       |       | 
|   3 |   NESTED LOOPS                         |         |     1 |   146 |   337   (0)| 00:00:02 |       |       | 
|   4 |    NESTED LOOPS                        |         |     1 |   115 |   336   (0)| 00:00:02 |       |       | 
|   5 |     NESTED LOOPS                       |         |     1 |    72 |   334   (1)| 00:00:02 |       |       | 
|   6 |      MERGE JOIN CARTESIAN              |         |     1 |    35 |   329   (0)| 00:00:02 |       |       | 
|   7 |       INDEX FULL SCAN                  | FICDEP1 |     1 |    26 |   315   (0)| 00:00:02 |       |       | 
|   8 |       BUFFER SORT                      |         | 45493 |   399K|    14   (0)| 00:00:01 |       |       | 
|   9 |        INDEX FULL SCAN                 | NATACF1 | 45493 |   399K|    14   (0)| 00:00:01 |       |       | 
|  10 |      PARTITION RANGE ALL               |         |    13 |   481 |     4   (0)| 00:00:01 |     1 |    45 | 
|  11 |       TABLE ACCESS BY LOCAL INDEX ROWID| FICNEG  |    13 |   481 |     4   (0)| 00:00:01 |     1 |    45 | 
|  12 |        INDEX RANGE SCAN                | FICNEG2 |     1 |       |     4   (0)| 00:00:01 |     1 |    45 | 
|  13 |     PARTITION RANGE SINGLE             |         |     1 |    43 |     2   (0)| 00:00:01 |   KEY |   KEY | 
|  14 |      TABLE ACCESS BY LOCAL INDEX ROWID | MATCLO  |     1 |    43 |     2   (0)| 00:00:01 |   KEY |   KEY | 
|  15 |       INDEX RANGE SCAN                 | MATCLO2 |   899 |       |     1   (0)| 00:00:01 |   KEY |   KEY | 
|  16 |    TABLE ACCESS BY GLOBAL INDEX ROWID  | FICNEG  |     1 |    31 |     1   (0)| 00:00:01 | ROW L | ROW L | 
|  17 |     INDEX UNIQUE SCAN                  | FICNEG1 |     1 |       |     1   (0)| 00:00:01 |       |       | 
------------------------------------------------------------------------------------------------------------------

La requête reste bloquée pendant des heures.
Il n'y a pas de stats sur les tables MATCLO, FICDEP et FICNEG mais le paramètre OPTIMZER_DYNAMIC_SAMPLING est positionné à 2.
Par contre, les stats sont présentes pour NATACF.

Cette requête est exécutée via notre progiciel.
En exécutant la même requête à part sous sqlplus et sur la même base du client celle ci s'exécute instantanément.

En killant la session et en relancant l'application, la session reste bloquée tjr sur la même requête et tjr avec le même événement d'attente.

En modifiant la vue pour y rajouter les critères de partitionnement le problème ne se pose plus et le plan d'execution devient le 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
Après 
 
------------------------------------------------------------------------------------------------------------------- 
| Id  | Operation                               | Name    | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop | 
------------------------------------------------------------------------------------------------------------------- 
|   0 | SELECT STATEMENT                        |         |       |       |     8 (100)|          |       |       | 
|   1 |  FILTER                                 |         |       |       |            |          |       |       | 
|   2 |   FAST DUAL                             |         |     1 |       |     2   (0)| 00:00:01 |       |       | 
|   3 |   NESTED LOOPS                          |         |     1 |    92 |     6   (0)| 00:00:01 |       |       | 
|   4 |    NESTED LOOPS                         |         |     1 |    78 |     5   (0)| 00:00:01 |       |       | 
|   5 |     NESTED LOOPS                        |         |     1 |    49 |     4   (0)| 00:00:01 |       |       | 
|   6 |      NESTED LOOPS                       |         |     1 |    28 |     3   (0)| 00:00:01 |       |       | 
|   7 |       PARTITION RANGE SINGLE            |         |    20 |   220 |     1   (0)| 00:00:01 |   KEY |   KEY | 
|   8 |        TABLE ACCESS BY LOCAL INDEX ROWID| FICDEP  |    20 |   220 |     1   (0)| 00:00:01 |   KEY |   KEY | 
|   9 |         INDEX RANGE SCAN                | FICDEP4 |     1 |       |     1   (0)| 00:00:01 |   KEY |   KEY | 
|  10 |       PARTITION RANGE SINGLE            |         |     1 |    17 |     1   (0)| 00:00:01 |   KEY |   KEY | 
|  11 |        TABLE ACCESS BY LOCAL INDEX ROWID| MATCLO  |     1 |    17 |     1   (0)| 00:00:01 |   KEY |   KEY | 
|  12 |         INDEX RANGE SCAN                | MATCLO2 |     1 |       |     1   (0)| 00:00:01 |   KEY |   KEY | 
|  13 |      TABLE ACCESS BY GLOBAL INDEX ROWID | FICNEG  |     1 |    21 |     1   (0)| 00:00:01 | ROW L | ROW L | 
|  14 |       INDEX UNIQUE SCAN                 | FICNEG1 |     1 |       |     1   (0)| 00:00:01 |       |       | 
|  15 |     TABLE ACCESS BY GLOBAL INDEX ROWID  | FICNEG  |     1 |    29 |     1   (0)| 00:00:01 | ROW L | ROW L | 
|  16 |      INDEX UNIQUE SCAN                  | FICNEG1 |     1 |       |     1   (0)| 00:00:01 |       |       | 
|  17 |    TABLE ACCESS BY INDEX ROWID          | NATACF  |     1 |    14 |     1   (0)| 00:00:01 |       |       | 
|  18 |     INDEX UNIQUE SCAN                   | NATACF1 |     1 |       |     1   (0)| 00:00:01 |       |       | 
-------------------------------------------------------------------------------------------------------------------

Pourquoi ce pb s'est il posé? pourquoi dans le premier plan d'execution fait-il un produit cartesien ? pourquoi la session reste en attente sur l'événement LATCH cache Buffer chains ? Est-ce dû à des statistiques fausses? faut-il augmenter le degré du dynamic_sampling?

je dois fournir une explication au client et là je n'en ai pas vraiment.

merci de votre aide

11/06/2009, 16h26
orafrance

Apparemment dans un cas il utilise l'index global et parcourt toutes les partitions contre l'utilisation de l'index local dans le deuxième cas.
11/06/2009, 16h30
farenheiit

Quel rapport avec l'evenement d'attente Latch cache buffer chains?
pourquoi fait il un produit cartesien s'il parcourt toutes les partitions ?
11/06/2009, 16h34
orafrance

c'est pas un produit cartesian, c'est juste une méthode de rapprochement de 2 FULL INDEX. Par contre comme tu parcours tous les blocs de l'index ça fait pas mal de bloc en mémoire à charger/décharger :?
11/06/2009, 16h49
pifor

Si vous êtes absolument sûr que la requête est complètement bloquée dans un cas, alors c'est forcément un bug.
11/06/2009, 16h53
farenheiit

Citation:

Envoyé par pifor

Si vous êtes absolument sûr que la requête est complètement bloquée dans un cas, alors c'est forcément un bug.

un bug oracle?
11/06/2009, 16h54
farenheiit

Citation:

Envoyé par orafrance

c'est pas un produit cartesian, c'est juste une méthode de rapprochement de 2 FULL INDEX. Par contre comme tu parcours tous les blocs de l'index ça fait pas mal de bloc en mémoire à charger/décharger :?

Sur ORAfaq on me dit qu'il fait bien un produit cartesien car l'Optimiseur part du principe que le full index scan ne lui retournera qu'une seule ligne, et donc un produit cartesien avec une seule ligne d'un côté n'est pas du tout couteux
11/06/2009, 17h00
pifor

Citation:

Envoyé par farenheiit

un bug oracle?

Oui et dans ce cas là, il faut contacter le support Oracle qui a des scripts pour analyser ce genre de situations.

Il faudrait aussi comprendre ce qui provoque la différence de comportement entre l'appli. et SQL*Plus: un ALTER SESSION dans le code ou un trigger on LOGON ? Le fichier de trace SQL (avec DBMS_MONITOR et les waits) des 2 exécutions pourrait aider.
11/06/2009, 17h14
orafrance

Citation:

Envoyé par pifor

Si vous êtes absolument sûr que la requête est complètement bloquée dans un cas, alors c'est forcément un bug.

Je ne vois pas pourquoi ? Si dans le deuxième cas, il limite le nombre de partitions parcourus c'est forcément moins bloquant :koi:

Les stats sont bien à jour ?

Déjà l'IFS n'est peut-être pas pertinent, faudrait essayer un FULL TABLE SCAN dans ce cas ;)
11/06/2009, 17h18
pifor

Je veux dire: si la requête est en attente sur le même latch indéfiniment et donc ne fait plus rien d'autre que d'attendre sur le même latch, c'est complètement anormal.
11/06/2009, 17h21
farenheiit

Justement 3 tables sur 4 n'ont pas de stats mais l'optimizer_dynamic_sampling est positionné à 2.
Le pb est que seul ce client a partitionné ces tables.
Les autres clients n'ont pas de partitions mais ont par contre des stats calculés via dbms_stats après chaque grosse MAJ.
Il n'y pas de stats pour ce client là car ils ont beaucoup de traitement qui sont executés en même temps. On a donc opté pour le dynamic_sampling. globalement les perfs sont meilleurs sauf que dans certains cas on n'a ce genre de pb.
11/06/2009, 17h22
orafrance

Avoir du cache buffer chains pendant des heures sur une requête gigantesque n'a rien d'étonnant. Ca veut juste dire qu'il ramasse un paquet de bloc :?
11/06/2009, 17h23
orafrance

Citation:

Envoyé par farenheiit

Justement 3 tables sur 4 n'ont pas de stats mais l'optimizer_dynamic_sampling est positionné à 2.
Le pb est que seul ce client a partitionné ces tables.
Les autres clients n'ont pas de partitions mais ont par contre des stats calculés via dbms_stats après chaque grosse MAJ.
Il n'y pas de stats pour ce client là car ils ont beaucoup de traitement qui sont executés en même temps. On a donc opté pour le dynamic_sampling. globalement les perfs sont meilleurs sauf que dans certains cas on n'a ce genre de pb.

Bah à mon avis, c'est de ce coté là qu'il faut chercher :?

D'après ce lien : http://momendba.blogspot.com/2008/08...artitions.html ça fait pas bon ménage avec les partitions... à voir.
11/06/2009, 17h35
orafrance

Visiblement le problème a déjà été identifié : https://metalink2.oracle.com/metalin...,1,1,helvetica

IFS + automatic_sampling = problème :?

De plus sur les tables partitionnées chaque jour sont effectués beaucoup de suppressions.
Sur les tables du client en question si je regarde les indexes je me rend compte que la fragmentation est plus que présent.
ex:
Code:

1 2 3 4 5 analyze index MATCLO1 validate structure; select name, height, lf_rows,del_lf_rows, round(del_lf_rows/decode(del_lf_rows,0,1,lf_rows)*100,2) ratio from index_stats;
j'obtiens le résultat suivant:
Code:

1 2 3 NAME HEIGHT LF_ROWS DEL_LF_ROWS RATIO ------------------------------ ---------- ---------- ----------- ---------- MATCLO1 3 39384 37975 96,42
Est-ce que la fragmentation des indexes peut jouer sur mon problème?
certains me disent que la fragmentation des indexes n'est plus d'actualité en 10g....:?

12/06/2009, 09h18
farenheiit

Citation:

Envoyé par orafrance

Visiblement le problème a déjà été identifié : https://metalink2.oracle.com/metalin...,1,1,helvetica

IFS + automatic_sampling = problème :?

Je ne vois pas le rapport entre cette note metalink et mon probleme!!!
Ils ne parlent même pas d'IFS

Finalement le problème n'est pas dû au partitionning mais uniquement au dynamic sampling et un HWM très élevé par rapport au nombre réel de lignes.

Par exemple dans la table MATCLO de mon exemple précédent on est censé récupéré 1500 lignes mais l'optimiseur pense qu'il n' y en a pas. Du coup il fait un merge join cartesian et ça plombe ma requête.

Le dynamic sampling ne trouve pas de lignes car dans ma partition j'ai 1500 lignes pour un HWM de 4000 blocks. je me retrouve dans cette situation car un moment il y'a eu bcp d'insertion dans la table puis un gros delete (pas possible de faire un truncate) puis un petit insert. Comme par defaut le nombre de blocks samplés par le dynamic sampling est de 32 (paramètre _optimizer_dyn_smp_blks) il a (4000-32)/4000 chances de tomber que sur des blocks vides.

Les solutions sont:
- soit de redescendre la HWM
- soit de monter la valeur du paramètre _optimizer_dyn_smp_blks

vous pouvez reproduire ce pb facilement de la manière suivante:

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
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
 
alter session set optimizer_dynamic_sampling=2;
 
alter session set "_optimizer_dyn_smp_blks"=32; -- default value
 
drop table d1 purge;
 
create table d1( i number, j number, k varchar2(80)) ;
begin 
  for i in 1..500000 loop 
    insert into d1 values( 0, i, 'AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA'); 
  end loop; 
  commit; 
end; 
/
 
 
-- Affichage des différents blocks de la tables avec le nombre de lignes dans chacun d'eux
select dbms_rowid.ROWID_BLOCK_NUMBER(a.rowid), count(1) 
from  d1 a 
group by dbms_rowid.ROWID_BLOCK_NUMBER(a.rowid);
 
 
-- effacer toutes les données sauf celle contenues dans un bloc afin de causer une forte fragmentation
 
delete from d1 a where dbms_rowid.ROWID_BLOCK_NUMBER(a.rowid) != 449826;
 
commit;
 
explain plan for
select * from d1;
 
select * from table(dbms_xplan.display());
 
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
Plan hash value: 396716558
 
--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |     1 |    68 |  1029   (1)| 00:00:13 |
|   1 |  TABLE ACCESS FULL| D1   |     1 |    68 |  1029   (1)| 00:00:13 |
--------------------------------------------------------------------------
 
Note
-----
 
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
   - dynamic sampling used for this statement
 
CONTOURNEMENT 1
===============
Reconstruire la table
 
alter table D1 move;
 
explain plan for
select * from d1;
 
select * from table(dbms_xplan.display());
 
 
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
Plan hash value: 396716558
 
--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |   132 |  8976 |     2   (0)| 00:00:01 |
|   1 |  TABLE ACCESS FULL| D1   |   132 |  8976 |     2   (0)| 00:00:01 |
--------------------------------------------------------------------------
 
Note
-----
 
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
   - dynamic sampling used for this statement
 
 
CONTOURNEMENT 2
===============
Changer le nombre des blocs visités par le dynamic sampling
 
alter session set "_optimizer_dyn_smp_blks"=4096;  
-- 128 times the default size
 
explain plan for
select * from d1;
 
select * from table(dbms_xplan.display());
 
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
Plan hash value: 396716558
 
--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |   132 |  8976 |  1029   (1)| 00:00:13 |
|   1 |  TABLE ACCESS FULL| D1   |   132 |  8976 |  1029   (1)| 00:00:13 |
--------------------------------------------------------------------------
 
Note
-----
 
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
   - dynamic sampling used for this statement

19/06/2009, 21h04
Waldar

Je dis peut-être une bétise n'étant pas DBA et n'ayant pas compris tous les propos de ce sujet, mais ne serait-ce pas simplement lié à celà :

Citation:

Il n'y pas de stats pour ce client là car ils ont beaucoup de traitement qui sont executés en même temps

Si vous faites du parallel gather stats sur un pourcentage raisonnable des données ça reste inenvisageable ?
19/06/2009, 21h49
NGasparotto

Citation:

Envoyé par farenheiit

Justement 3 tables sur 4 n'ont pas de stats mais l'optimizer_dynamic_sampling est positionné à 2.

Je ne comprends pas cette phrase.
Il n'y a pas de stats mais optimizer_dynamic_sampling=2, et alors ? En 10gR2, 2 est la valeur par defaut, je ne vois pas bien l'argumentaire.
S'il n'y a pas de stats du tout, alors c'est potentiellement un probleme.
Puis quand tu dis que la requete est bloquee pendant des heures, y-a-t'il une reponse ou rien du tout ? Depuis quand ? Est-ce que ca a deja fonctionne ?
Avant de partir dans des suppositions plus ou moins credibles et de jouer avec des parametres caches, je ferais un tkprof si possible, et calculerais les stats. Apres tout, comme l'a dit Waldar precedemment, avec un parallele et un estimate a 0.001 voir meme moins ca peut aller vite. Et meme un estimate 0.0001 n'est jamais loin de la realite.
Apres tout, tu es en 10gR2, en 10gR2 on est en CBO, en CBO on a besoin des stats, meme avec optimizer_dynamic_sampling=2...

Nicolas.
19/06/2009, 21h59
NGasparotto

Citation:

Envoyé par farenheiit

...Comme par defaut le nombre de blocks samplés par le dynamic sampling est de 32 (paramètre _optimizer_dyn_smp_blks) il a (4000-32)/4000 chances de tomber que sur des blocks vides....

Juste une petite precision, si dynamic_sampling=2, alors ce n'est pas 32 (valeur du paramètre _optimizer_dyn_smp_blks) blocks qui sont samples, mais 2*32.
pour dynamic_sampling=0, pas de sampling
pour dynamic_sampling=1, 1*32
pour dynamic_sampling=2, 2*32
pour dynamic_sampling=3, 4*32
pour dynamic_sampling=4, 8*32
...
jusqu'a dynamic_sampling=9, 256*32.

Et comme par defaut en 10gR2 dynamic_sampling=2, c'est donc 64 blocks qui sont samples par defaut.

Nicolas.