la requête est dans combien de fichiers ?
Inscrivez-vous gratuitement
pour pouvoir participer, suivre les réponses en temps réel, voter pour les messages, poser vos propres questions et recevoir la newsletter
Discussion :
la requête est dans combien de fichiers ?
J'ai un fichier de traces de 800mo dans lequel la requête est appelée de nombreuses fois.
Le fichier init.ora :
Code : Sélectionner tout - Visualiser dans une fenêtre à part
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
113
114
115
116
il me semble me rappeller qu'il y a un but sur le elapsed...
j'ai de scripts magique à vous proposer, mais il faut réussier à sortir cette requête de la trace, sans tout synthétiser..
Compressé, le fichier de traces ne fait plus que 36mo au lieu de 800, mais je ne peux pas l'envoyer par le système d'upload de free par exemple car c'est bloqué par le proxy... et il y a tellement de requêtes éparpillées dans le fichier que cela me semble difficile de faire le tri...
Je peux toutefois en afficher deux exemples qui sont intéressants, on voit bien un elapsed time énorme!!!
Dans les traces, a chaque fois , il y a 2 requêtes à la suite qui sont proches (not null pas au même endroit), une qui se passe bien, et l'autre non.
1er exemple des 2 requêtes dans les traces:
2eme exemple des 2 requêtes dans les traces:
Code : Sélectionner tout - Visualiser dans une fenêtre à part
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
On retrouve bien ces résultats dans l'analyse de tkprof ci -dessous.
Code : Sélectionner tout - Visualiser dans une fenêtre à part
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
Requête tkpof qui se passe bien :
Code : Sélectionner tout - Visualiser dans une fenêtre à part
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
27select f.regime_circ from rep_pr r,rep_fiche f where r.ci_pr= :1 and r.id_fiche=:2 and r.id_fiche=f.id and r.heure_local_arr is not null and r.heure_local_dep is null call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 39832 0.59 0.59 0 0 0 0 Execute 39832 1.51 1.24 0 0 0 0 Fetch 39832 4.14 57.04 13307 303305 0 38027 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 119496 6.25 58.89 13307 303305 0 38027 Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 23 Rows Row Source Operation ------- --------------------------------------------------- 1 NESTED LOOPS 1 TABLE ACCESS BY INDEX ROWID REP_FICHE 1 INDEX UNIQUE SCAN PK_REP_FICHE (object id 7020) 1 TABLE ACCESS BY INDEX ROWID REP_PR 16 INDEX RANGE SCAN IX_REP_PR_01 (object id 7032) ********************************************************************************
Requête tkprof qui se passe mal :
Code : Sélectionner tout - Visualiser dans une fenêtre à part
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******************************************************************************** select f.regime_circ from rep_pr r,rep_fiche f where r.ci_pr= :1 and r.id_fiche=:2 and r.id_fiche=f.id and r.heure_local_arr is null and r.heure_local_dep is not null call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 41472 0.84 0.61 0 0 0 0 Execute 41472 1.25 1.33 0 0 0 0 Fetch 41472 3.064154498643.93 18673 291584 0 39832 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 124416 5.154154498645.89 18673 291584 0 39832 Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 23 Rows Row Source Operation ------- --------------------------------------------------- 1 NESTED LOOPS 1 TABLE ACCESS BY INDEX ROWID REP_FICHE 1 INDEX UNIQUE SCAN PK_REP_FICHE (object id 7020) 1 TABLE ACCESS BY INDEX ROWID REP_PR 1 INDEX RANGE SCAN IX_REP_PR_01 (object id 7032)
Orafrance, je ne comprends pas ce que tu veux dire par là ? but ?
il me semble me rappeller qu'il y a un but sur le elapsed...
Conclusion : tkprof ne bug pas.
donc l'elapsed est réellement important
donc là, faut avoir les wait. il n'y a plus le choix !
Il suffit de lancer 1 requête en trace level 8 et d'uploader la trace
y'a peut-être pas de bug mais passé d'un e=10180 à elapsed 4154498643.93 ça me parait pas très catholique
M'enfin, n'en reste pas moins qu'on a toujours pas le wait
En effet, il y a bien quelque chose qui cloche dans mon analyse. Surtout que je n'avais pas bien vu que même pour la requête suivante il y a parfois des temps de fetch importants.
select f.regime_circ from rep_pr r,rep_fiche f where r.ci_pr= :1 and r.id_fiche=:2 and r.id_fiche=f.id and r.heure_local_arr is not null and
r.heure_local_dep is null
Dans les traces oracles brutes, d'après ce que j'ai lu, c'est en centièmes de secondes. Donc quand il y a 10180 cela fait tout de même 101 secondes! Et cette requête est appelée 41472 fois dans les traces qui ne représentent qu'une partie du traitement! Il semble donc bien qu'il y ait un pb ici. (100 seconde par requête * 40000 requêtes = 4 million de secondes tout de même) On n'atteint cependant pas les 4154498645 indiqué par TKPROF.
Je suis désoléM'enfin, n'en reste pas moins qu'on a toujours pas le waitJ'aimerais aussi pouvoir les avoir mais je n'ai pas la main sur le serveur... ça va malheureusement devoir attendre 2 semaines ...
tu peux pas lancer la requête et regarder v$session_wait ? Statspack ne serait pas installé par hasard ?
Durant les 24h de traitements, n'y a t-il pas d'autres traitements en cours (calculs d'agrégats, bilan comptable, sauvegarde, refresh de statistiques...) ?
Le serveur est-il bien dédié à la base Oracle ?
Comment a été copiée la BD sur ce nouveau serveur (exp/imp, copie datafiles, duplicate rman...) ?
Même niveau de patch sur les 2 serveurs ?
Je ne connais pas windows mais sur unix, les file system avec cache sont parfois pénalisant coté perf. Oracle préfère accéder directement au disque. Si c'est idem sur windows, il y a peut être un problème coté cache disque.
4 millions de secondes = 1111 heures = 46 jours....
les chiffres ne sont pas aussi élevés que ça... il y a donc bien un bug quelque part... en plus de la lenteur !
comment avez-vous activé la trace ?
quelle est la version exacte ? (OS, level, ...)
Non, il n'y a pas d'autres traitements.Durant les 24h de traitements, n'y a t-il pas d'autres traitements en cours (calculs d'agrégats, bilan comptable, sauvegarde, refresh de statistiques...) ?
Le serveur est-il bien dédié à la base Oracle ?
Comment a été copiée la BD sur ce nouveau serveur (exp/imp, copie datafiles, duplicate rman...) ?
Même niveau de patch sur les 2 serveurs ?
Je ne connais pas windows mais sur unix, les file system avec cache sont parfois pénalisant coté perf. Oracle préfère accéder directement au disque. Si c'est idem sur windows, il y a peut être un problème coté cache disque.
Pour la copie de la base sur le serveur, j'avoue que je ne connais pas la façon dont cela a été fait.
Tout est sur le même serveur : Application en Delphi et serveur oracle.
Oracle 9.2.0 est installé sur les 2 serveurs.
Pour le cache disque, je ne vois pas trop comment regarder cela. Les disques sont des SCSI en raid 1. (1 paire de disques 146 go SCSI 10000 tours/min et une paire de disques 36go 15000 tours / min)
L'activation des traces a été faite au niveau par défaut, avec les commandes suivantes :4 millions de secondes = 1111 heures = 46 jours....
les chiffres ne sont pas aussi élevés que ça... il y a donc bien un bug quelque part... en plus de la lenteur !
comment avez-vous activé la trace ?
quelle est la version exacte ? (OS, level, ...)
Code : Sélectionner tout - Visualiser dans une fenêtre à part
2
3
4
5
6
7
8
9
Je fais une petite pause sur ce pb... mais je vais m'y remettre dans 2 semaines
Merci pour l'aide que vous m'avez apporté!
Je suis de retour sur ce pb.
Un test avec 2Go de Ram au lieu de 1Go a été fait. Les performances ne sont pas améliorées.
J'ai demandé à ce qu'un test avec les traces oracle de niveau 8 soit effectué après que des traces classiques aient été faites (pour avoir plus d'infos sur les waits).
Cependant, cela n'a pas pu être faite car le processus de l'application n'est pas actif d'après oracle. La connexion à sqlplus était bien faite en tant que sysdba. Je ne comprends pas pourquoi l'activation n'a pas fonctionné.
En particulier la ligne suivante qui aurait dû fonctionner :
Code : Sélectionner tout - Visualiser dans une fenêtre à part oradebug setospid 832
Pendant le traitement, le processeur n'est pas surchargé :
C'est vraiment frustrant ce problème de perf
Version de windows ?
Peut-on savoir quelle est la version précise de windows ? Est-on en 32 bits ou en 64 bits ? Sur les deux serveurs ?
ora-72 : pas le bon spid/pid
ora-73 : commande pas terminée correctement
insistez auprès du support oracle pour qu'il vous aide jusqu'au bout !!!
Concernant la version de windows, dans un premier temps, des tests avaient été fait sous windows 2003 server.
Etant donné que les perfs n'étaient pas bonnes, Windows 2000 Sp4 (32bits) a été installé à la place .
Le processeur est un Xeon 3ghz bi-coeur 32 bits.
A priori, un nouveau test devrait être fait lundi ou mardi, on va réessayer d'activer les traces de niveau 8.
Ok, je voulais être sûr
Extrait de la note Metalink 161546.1 :
"...
Microsoft has certified the Windows 2000, Windows XP 32-Bit and Windows 2003
32-Bit operating systems to run on the AMD 64-Bit Opteron processor and the
Intel 64-Bit Xeon processor (Xeon processors with Intel EM64T support). From
version 9.2.x Oracle has certified its 32-Bit database and client software to
run on these 32-Bit operating systems running on these 64-Bit processors.
..."
Reste maintenant à savoir si la version d'Oracle installée est une version 32-bits ou 64-bits ?
4 milliards, c'est la limite haute d'un entier non signé sur 32-bits (pour être plus précis : 4294967296 - 1).
Ah et peut-être qu'en fouillant cela
tu trouveras des infos.
Good luck!
Merci pour ces infos.
Après un nouveau test, ce fetch énorme n'est pas réapparu sur la même requête , mais sur une autre requête !
En fait maintenant je suis à peu près sur que c'est un bug de la génération des traces oracle puisque la nouvelle requête sur laquelle le pb est apparu s'est effectuée correctement dans un temps normal. En plus, j'ai pu retrouver dans les traces oracle brutes les 5 exécutions de la requête avec des valeurs qui sont parfois énormes:
Code : Sélectionner tout - Visualiser dans une fenêtre à part
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
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
Requêtes qui prennent le plus de temps (avec le bug présent sur la première requête):
Code : Sélectionner tout - Visualiser dans une fenêtre à part
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
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185******************************************************************************** count = number of times OCI procedure was executed cpu = cpu time in seconds executing elapsed = elapsed time in seconds executing disk = number of physical reads of buffers from disk query = number of buffers gotten for consistent read current = number of buffers gotten in current mode (usually for update) rows = number of rows processed by the fetch or execute call ******************************************************************************** select d.id_fiche_sncf,r.id as idRep from dem_fiche d, dem_pr dr, rep_fiche r, rep_pr pr where r.Liste_id_fiche_sncf is null and r.parite is null and d.id = dr.id_fiche and r.id = pr.id_fiche and pr.ci_pr=dr.ci_pr and pr.ch_pr=dr.ch_pr and (( r.num_sillon_reponse = d.num_sillon1 ) or ( r.num_sillon_reponse = d.num_sillon2 )) and d.id_fiche_sncf like :1 and not exists (select id_rep_fiche from correspondance where id_rep_fiche = r.id) and ((dr.heure_local_dep is null and pr.heure_local_dep is null and dr.heure_local_arr is not null and pr.heure_local_arr is not null) or (dr.heure_local_arr is null and pr.heure_local_arr is null and dr.heure_local_dep is not null and pr.heure_local_dep is not null)) and ((abs(to_number(dr.heure_local_arr) - to_number(pr.heure_local_arr)) <= :2) or (abs(to_number(dr.heure_local_dep) - to_number(pr.heure_local_dep)) <= :3)) call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 5 0.00 0.00 0 0 0 0 Execute 5 0.00 0.00 0 0 0 0 Fetch 14 825.934154499735.23 173793 849453 0 1139 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 24 825.934154499735.24 173793 849453 0 1139 Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 23 Rows Row Source Operation ------- --------------------------------------------------- 14 FILTER 6852 NESTED LOOPS 36508 HASH JOIN 956626 TABLE ACCESS BY INDEX ROWID REP_PR 983686 NESTED LOOPS 27059 TABLE ACCESS FULL REP_FICHE 956626 INDEX RANGE SCAN IX_REP_PR_01 (object id 7635) 379408 TABLE ACCESS FULL DEM_PR 6852 TABLE ACCESS BY INDEX ROWID DEM_FICHE 36508 INDEX UNIQUE SCAN PK_DEM_FICHE (object id 7516) 6312 INDEX RANGE SCAN IX_CORRESPONDANCE_02 (object id 7631) ******************************************************************************** INSERT INTO Ecart (Id, Id_Fiche_Sncf, Rang, Id_Fiche_Rep, Id_Pr_Rep, Type_Ecart, Description) VALUES (Sq_Ecart_01.NEXTVAL, :1, :2, :3, :4, :5, :6) call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 412128 6.60 5.27 0 5 0 0 Execute 412128 232.15 592.11 109 495156 4997668 400141 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 824256 238.76 597.39 109 495161 4997668 400141 Misses in library cache during parse: 1 Misses in library cache during execute: 2 Optimizer goal: CHOOSE Parsing user id: 23 Rows Row Source Operation ------- --------------------------------------------------- 1 SEQUENCE ******************************************************************************** ANALYZE TABLE REP_PR COMPUTE STATISTICS call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 1 123.75 181.05 70675 71570 50 0 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 2 123.75 181.06 70675 71570 50 0 Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 23 ******************************************************************************** update seq$ set increment$=:2,minvalue=:3,maxvalue=:4,cycle#=:5,order$=:6, cache=:7,highwater=:8,audit$=:9,flags=:10 where obj#=:1 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 476558 16.78 15.37 0 0 0 0 Execute 476558 62.89 64.13 15 476595 973509 476558 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 953116 79.67 79.51 15 476595 973509 476558 Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: SYS (recursive depth: 1) Rows Row Source Operation ------- --------------------------------------------------- 1 UPDATE 1 INDEX UNIQUE SCAN I_SEQ1 (object id 107) ******************************************************************************** update Dem_Fiche set Traite = :1 where No_Demande_Rff = :2 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 43976 0.78 0.68 0 0 0 0 Execute 43976 68.25 69.74 88 132108 222611 43976 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 87952 69.03 70.42 88 132108 222611 43976 Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 23 Rows Row Source Operation ------- --------------------------------------------------- 0 UPDATE 1 TABLE ACCESS BY INDEX ROWID DEM_FICHE 1 INDEX RANGE SCAN IX_DEM_FICHE_03 (object id 7519) ******************************************************************************** INSERT INTO Correspondance (Id, Id_Dossier, Id_Rep_Fiche,CAS) VALUES (Sq_Correspondance_01.NEXTVAL, :1, :2,:3) call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 64420 1.00 0.88 0 0 0 0 Execute 64420 35.98 49.64 807 67061 891846 64420 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 128840 36.98 50.53 807 67061 891846 64420 Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 23 Rows Row Source Operation ------- --------------------------------------------------- 1 SEQUENCE ********************************************************************************
Bref, maintenant je commence à écarter la piste de problème oracle qui expliquerait les mauvaises perf de l'application.
tout ça pour en arriver au résultat du 2° post de cette discussion... Oracle nous réserve parfois de sales coups
Vous avez un bloqueur de publicités installé.
Le Club Developpez.com n'affiche que des publicités IT, discrètes et non intrusives.
Afin que nous puissions continuer à vous fournir gratuitement du contenu de qualité, merci de nous soutenir en désactivant votre bloqueur de publicités sur Developpez.com.
Répondre avec citation
Partager