Discussion :

[debdba]

Bonjour,
Pour bénéficier des améliorations de la 10g, j'ai migrée une instance depuis Oracle 9.2.0.5 vers 10.2.0.1.
Et là: catastrophe!
Une requete qui habituellement met 3mn, affiche sur la console entreprise manager prés de 20h. et avance à trés petits pas de block.

Les plans d'accés sont identiques avec l'instance en 9i qui a la mème volumétrie (~700000 lignes), il s'agit d'un full scan de la table, car les index sont inhibés par la requete.
Que je mette une sga_target à 900M, ou que je modifie le .ora avec 700M de db_cache_size et 200M de shared_pool j'ai la mème situation catastrophique.
Je ne sais quelle direction prendre pour comprendre
Je me connecte directement au niveau du serveur base de données par

Code :

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

1
2
sqlplus user/password
select * from matable where (ol1(varchar2) not like 'X%' or to_date(col1, 'YYYYMMDD') > to_date(20080710', 'YYYYMMDD'))

Avez vous une idée d'orientation de recherches

Par avance merci

[orafrance]

si col1 est un NUMBER tu peux déjà supprimer le TO_DATE et il n'ai pas possible de faire en sorte que la fonction ol1 retourne 1 seul caractère :

Code :

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

SELECT * FROM matable WHERE ol1(varchar2) <> 'X' OR col1 > 20080710

Pourquoi 10.2.0.1 et pas 10.2.0.3 ou plus ?

T'as comparé les paramètres des 2 instances comme disk_asynch_io, hash_area_size, hash_join_enabled, optimizer_*, parallélisme, etc ?

C'est la même machine ? La charge CPU ou I/O sur la machine n'est pas excessive ?

[debdba]

Les paramètres non obsolètes en 10g (comme hash_join_enabled) sont strictement identiques à ceux présents en 9i.
Il s'agit de 2 serveurs AIX différents celui en 10g est en 5.3, le serveur de la version 9I est en 4.3.
Lorsque la requete tourne en base 10g il n'y a aucune charge significative sur le serveur ni en cpu ni en IO, comme s'il ne se passait rien de particulier.

Par ailleurs je ne peux pas modifier la requete car il s'agit d'un progiciel livré ainsi.
De plus cette requete étant trés rapide en 9i je ne peux pas justifier une modification d'écriture.

Autre bizarerie, lorsque je regarde la requete au niveau Console Entreprise Manager, le status de la session est "inactive" malgré l'activité évidente bien que lente.

[orafrance]

faut alors la mettre en trace pour savoir ce qu'elle attend ou au moins regarder v$session_wait.

[debdba]

J'ai mis en place statpack et j'obtiens ceci

Cache Sizes Begin End
~~~~~~~~~~~ ---------- ----------
Buffer Cache: 652M Std Block Size: 8K
Shared Pool Size: 152M Log Buffer: 6,023K

Load Profile Per Second Per Transaction
~~~~~~~~~~~~ --------------- ---------------
Redo size: 432,440.26 56,467.91
Logical reads: 16,206.93 2,116.30
Block changes: 2,253.25 294.23
Physical reads: 10,706.55 1,398.06
Physical writes: 117.86 15.39

Instance Efficiency Percentages
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 34.04 In-memory Sort %: 99.93
Library Hit %: 93.74 Soft Parse %: 94.11
Execute to Parse %: 81.84 Latch Hit %: 99.98
Parse CPU to Parse Elapsd %: 28.76 % Non-Parse CPU: 99.87

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 91.92 88.34
% SQL with executions>1: 73.72 67.82
% Memory for SQL w/exec>1: 92.78 81.32

Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time
----------------------------------------- ------------ ----------- ------ ------
CPU time 11,657 59.2
db file sequential read 269,075,476 5,896 0 29.9
log file parallel write 79,659 618 8 3.1
db file parallel write 53,275 600 11 3.0
library cache pin 183 536 2930 2.7
-------------------------------------------------------------

Mème si j'augmente la taille de buffer_cache, le buffer hit est meilleur mais ma requete est toujours aussi lente

[orafrance]

c'est complétement inutile... c'est la vue instantanée de la session qu'il faut

[debdba]

Lorsque j'interromps le select le résultat de la trace est null

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
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        1      0.00       0.00          0          0          0           0
 
Misses in library cache during parse: 0
Misses in library cache during execute: 1
 
 
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      0      0.00       0.00          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------

Sinon je suis obligée d'attendre plus de 20heures!!!!

[orafrance]

le monsieur te dit : v$session_wait

[13thFloor]

Dans ton rapport statspack, que donnent les rubriques :
- PGA Aggr Target Stats
- Tablespace IO Stats
- File IO Stats
- Top 5 Logical Reads per Segment
- Top 5 Physical Reads per Segment

Si %PGA trop faible et beaucoup d'IO pour les datafiles du tablespace TEMP => accroissement de PGA à prévoir.
Il y a t-il des datafiles avec des temps d'accès supérieurs à 40ms ?
Les IO asynchrones ont bien été activées sur le serveur ?

[debdba]

Bonjour,

Voici le résultat de v$session_wait pour ma session

Code :

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

1
2
3
4
5
SQL> select seq#, event, wait_time as wait_time, state as state, p1text, p2text, p3text from v$session_wait where sid= 214;
      6481 SQL*Net message from client
         0 WAITING
driver id
#bytes

Etonnant car je suis au niveau du serveur de base de données et directement sur l'instance sans passer par un client quelconque

[orafrance]

BALISE CODE STP !!!!

et tu n'as que cet événement ? Exécute la requête plusieurs fois pour relever les différents évènements d'attente... du devrait au moins avoir du scattered read

Enfin, tu dis qu'il y a du Full Table mais on ne le vois pas dans le top 5 des attentes

[debdba]

Bonjour

j'ai eu enfin une trace malgré l'abort de la session

SELECT a.*
FROM tab1 a
WHERE (a.col1 not like 'A%' OR TO_DATE(a.col1, 'YYYYMMDD') >= TO_DATE('20080712', 'YYYYMMDD'))

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.04 0.06 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2845 0.26 3.67 14708 17151 0 42661
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2847 0.30 3.73 14708 17151 0 42661

Misses in library cache during parse: 1
Optimizer mode: CHOOSE
Parsing user id: 25 (INSTANCE)

Rows Row Source Operation
------- ---------------------------------------------------
42661 TABLE ACCESS FULL TAB1 (cr=17151 pr=14708 pw=0 time=1032240 us)


Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT MODE: CHOOSE
42661 TABLE ACCESS MODE: ANALYZED (FULL) OF 'TAB1' (TABLE)
********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.04 0.06 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2845 0.26 3.67 14708 17151 0 42661
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2848 0.30 3.73 14708 17151 0 42661

Misses in library cache during parse: 1
Misses in library cache during execute: 1

[orafrance]

on n'est pas plus avancé, c'est pas une trace de niveau 8 donc on n'a pas les événement d'attente

En tout cas, ça dure pas 20h et pourquoi tu ne montres pas TOUT le tkprof sys inclus ?

[debdba]

Au niveau du rapport statpack
Les io asynchrons sont bien activés
disk_asynch_io boolean TRUE

voici le résultat obtenu par statpack sur les rubriques demandées

Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time
----------------------------------------- ------------ ----------- ------ ------
CPU time 52 52.3
db file sequential read 362,267 20 0 20.3
SQL*Net message from dblink 39 12 295 11.6
db file parallel write 5,676 6 1 6.4
log file parallel write 1,900 4 2 4.2
-------------------------------------------------------------

Les io les plus nombreuses se font au niveau du datafile de données (table scan) : 0 - 2 ms = 173,687 et 32 et + ms = 2
Le tablespace le accédé en lecture est celui des données de la table lues
Le tablespace TEMP n'est pratiquement sollicité
In-memory Sort %: 100.00

résultat pour la PGA
PGA Cache Hit % W/A MB Processed Extra W/A MB Read/Written
--------------- ---------------- -------------------------
68.7 816 373

%PGA %Auto %Man
PGA Aggr Auto PGA PGA Mem W/A PGA W/A W/A W/A Global Mem
Target(M) Target(M) Alloc(M) Used(M) Mem Mem Mem Bound(K)
- --------- --------- ---------- ---------- ------ ------ ------ ----------
B 200 132 124.3 12.0 9.7 100.0 .0 40,960
E 200 128 158.1 16.9 10.7 100.0 .0 40,960
-------------------------------------------------------------


Par ailleurs la trace fournie est le résultat aprés une interruption volontaire de la requete au bout d'1 heure d'activité

[debdba]

Le mème mais avec les balises, grand Merci au modérateur



Au niveau du rapport statpack
Les io asynchrons sont bien activés

Code :

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

disk_asynch_io boolean TRUE

voici le résultat obtenu par statpack sur les rubriques demandées

Code :

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

1
2
3
4
5
6
7
8
9
10
Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time
----------------------------------------- ------------ ----------- ------ ------
CPU time 52 52.3
db file sequential read 362,267 20 0 20.3
SQL*Net message from dblink 39 12 295 11.6
db file parallel write 5,676 6 1 6.4
log file parallel write 1,900 4 2 4.2
-------------------------------------------------------------

Les io les plus nombreuses se font au niveau du datafile de données (table scan) : 0 - 2 ms = 173,687 et 32 et + ms = 2
Le tablespace le accédé en lecture est celui des données de la table lues
Le tablespace TEMP n'est pratiquement sollicité

Code :

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

In-memory Sort %: 100.00

résultat pour la PGA

Code :

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

1
2
3
4
5
6
7
8
9
10
11
PGA Cache Hit % W/A MB Processed Extra W/A MB Read/Written
--------------- ---------------- -------------------------
68.7 816 373
 
%PGA %Auto %Man
PGA Aggr Auto PGA PGA Mem W/A PGA W/A W/A W/A Global Mem
Target(M) Target(M) Alloc(M) Used(M) Mem Mem Mem Bound(K)
- --------- --------- ---------- ---------- ------ ------ ------ ----------
B 200 132 124.3 12.0 9.7 100.0 .0 40,960
E 200 128 158.1 16.9 10.7 100.0 .0 40,960
-------------------------------------------------------------

Par ailleurs la trace fournie est le résultat aprés une interruption volontaire de la requete au bout d'1 heure d'activité

[orafrance]

je ne vois toujours pas le Full Scan de la trace dans les événements d'attente de la base... une seule conclusion s'impose donc, c'est pas la requête qui prend 20h.

[debdba]

Et pourtant c'est bien ce qui est dans la trace

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
SELECT a.*
FROM tab1 a
WHERE (a.col1 not like 'A%' OR TO_DATE(a.col1, 'YYYYMMDD') >= TO_DATE('20080712', 'YYYYMMDD'))

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.04 0.06 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2845 0.26 3.67 14708 17151 0 42661
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2847 0.30 3.73 14708 17151 0 42661

Misses in library cache during parse: 1
Optimizer mode: CHOOSE
Parsing user id: 25 (INSTANCE)

Rows Row Source Operation
------- ---------------------------------------------------
42661 TABLE ACCESS FULL TAB1 (cr=17151 pr=14708 pw=0 time=1032240 us)


Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT MODE: CHOOSE
42661 TABLE ACCESS MODE: ANALYZED (FULL) OF 'TAB1' (TABLE)

Et avec la console entreprise manager

Code :

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

1
2
3
4
5
SELECT STATEMENT 
1  monschema.TAB1 TABLE ACCESS [FULL] 

Cette étape du plan extrait toutes les lignes de la table TAB1. 
19 125   709 174   479 939,045

Et idem dans la plan table lorsque je fais un explain de la requette
Merci encore

[orafrance]

Et pourtant c'est bien ce qui est dans la trace

Bah non, elapsed = 3.73 ça fait pas 20h ça

[debdba]

Je le sais bien puisque comme je vous l'ai indiqué dans une précédente réponse, je l'ai arrété volontairement avant la fin pour pouvoir avoir une trace.


J'ai relancé un autre select qui devrait bientôt aller jusqu'au bout pour lequel j'aurais une trace réelle du temps d'exécution complet.

[13thFloor]

Les io asynchrons sont bien activés

Code :

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

disk_asynch_io boolean TRUE

Je parlais des aio coté AIX : lsdev -C -t aio -S a

20h pour ramener 42000 lignes...il doit y avoir autre chose.