Problème performance oracle : Elapsed Time d'un Fetch énorme!

Version imprimable

Voir 40 message(s) de cette discussion en une page

Bonjour,

Une application DELPHI /Oracle 9.2 tourne actuellement sur un poste classique de façon correcte. Tout est sur le même serveur (application delphi + serveur oracle). Le poste est sous Windows XP.

Cette même application a été placé sur un nouveau serveur plus performant (XEON 3ghz double coeur, disques durs SCSI en RAID 1, sous windows 2003...) et les performances lors de l'exécution d'un traitement ont été divisé par 3/4 ce qui n'est pas acceptable.

On m'a chargé de détecter les causes de cette mauvaise performance.
Pendant les tests, il a été détecté qu'un seul coeur du processeur sur les 2 est utilisé par l'application en delphi ainsi que le serveur oracle. Cependant, cela ne semble pas être ce qui bride les performances puisque le processeur est rarement à 50 % (50% représentant la totalité de l'un des deux coeurs)

Un bench des disques dur a montré que les performances sont acceptables.

Une analyse des traces oracle du traitement avec TKPROF (800mo de traces oracle) donne les résultats suivants (certaines requêtes ont été enlevées pour que ce soit moins long) qui sont très étonnants au niveau du elapsed time du FETCH du "OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS", tout en bas

Le traitement dure de l'ordre de 24h au lieu de 5-6 heures sur l'ancien serveur.

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
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
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
TKPROF: Release 9.2.0.6.0 - Production on Wed Dec 19 18:11:28 2007

Copyright (c) 1982, 2002, Oracle Corporation.  All rights reserved.

Trace file: s2008_ora_4140.trc
Sort options: prscpu  execpu  fchcpu  
********************************************************************************
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.01          0          0          0           0
Execute      5      0.00       0.00          0          0          0           0
Fetch       15   1158.25    1318.85      93922    1156005          0        1565
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       25   1158.25    1318.87      93922    1156005          0        1565

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 23  

Rows     Row Source Operation
-------  ---------------------------------------------------
    134  FILTER  
  16734   NESTED LOOPS  
  61193    HASH JOIN  
 949001     TABLE ACCESS BY INDEX ROWID REP_PR 
 980877      NESTED LOOPS  
  31875       TABLE ACCESS FULL REP_FICHE 
 949001       INDEX RANGE SCAN IX_REP_PR_01 (object id 7032)
 322033     TABLE ACCESS FULL DEM_PR 
  16734    TABLE ACCESS BY INDEX ROWID DEM_FICHE 
  61193     INDEX UNIQUE SCAN PK_DEM_FICHE (object id 6866)
  15177   INDEX RANGE SCAN IX_CORRESPONDANCE_02 (object id 7028)

********************************************************************************

update Dem_Fiche set Traite = :1 
where
 No_Demande_Rff = :2


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse    35285      0.68       0.56          0          0          0           0
Execute  35285     64.84      65.57        110     105973     178489       35285
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    70570     65.53      66.14        110     105973     178489       35285

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 6869)

********************************************************************************

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     62.51      90.82      31219      36093         30           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2     62.51      90.82      31219      36093         30           0

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 23  
********************************************************************************

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    40544      0.57       0.64          0          0          0           0
Execute  40544     26.31      30.84        380      42258     550101       40544
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    81088     26.89      31.48        380      42258     550101       40544

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 23  

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SEQUENCE  

********************************************************************************

update dem_fiche set traite=null


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0         43          0           0
Execute      1     25.82      29.25         62       8336     166676       47470
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2     25.82      29.25         62       8379     166676       47470

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 23  

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  UPDATE  
  47470   TABLE ACCESS FULL DEM_FICHE 

********************************************************************************

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    30988      0.40       0.42          0          5          0           0
Execute  30988     17.92      18.58         34      31408     348505       30988
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    61976     18.32      19.01         34      31413     348505       30988

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  

********************************************************************************

select Heure_Local_Arr, Heure_Local_Dep, Ci_Pr
  from Dem_Pr
 where Rang = :1
   and Id_Fiche = :2

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse   177926      3.29       2.35          0          0          0           0
Execute 177926      5.85       5.38          0          0          0           0
Fetch   355852      6.98      23.29       4359     889629          0      177926
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   711704     16.14      31.03       4359     889629          0      177926

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 23  

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  TABLE ACCESS BY INDEX ROWID DEM_PR 
      1   INDEX RANGE SCAN IX_DEM_PR_01 (object id 6876)

********************************************************************************

ANALYZE TABLE DEM_PR COMPUTE STATISTICS


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1     11.42      12.67       1686       6175          8           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2     11.42      12.67       1686       6175          8           0

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 23  
********************************************************************************



********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse   780651     13.09      11.46          3        138          0           0
Execute 780651    270.87     337.93      62476     661420    2080424      298576
Fetch   1000494   1191.574154500164.68     155322    3913556         15      686045
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   2561796   1475.544154500514.08     217801    4575114    2080439      984621

Misses in library cache during parse: 61
Misses in library cache during execute: 3


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse   287495      5.12       4.79          6        278          0           0
Execute 590483     35.32      48.31       2437     327949     284873      161652
Fetch   435566     10.51      55.24      12000    1474151          2      435124
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   1313544     50.96     108.35      14443    1802378     284875      596776

Misses in library cache during parse: 134
Misses in library cache during execute: 2

994853  user  SQL statements in session.
73295  internal SQL statements in session.
1068148  SQL statements in session.
********************************************************************************
Trace file: s2008_ora_4140.trc
Trace file compatibility: 9.02.00
Sort options: prscpu  execpu  fchcpu  
       1  session in tracefile.
  994853  user  SQL statements in trace file.
   73295  internal SQL statements in trace file.
  1068148  SQL statements in trace file.
     191  unique SQL statements in trace file.
 14728913  lines in trace file.

Est-ce que vous avez une explication de ce fetch énorme ? (d'ailleurs les valeurs sont si grandes que cela ne peut pas être possible)

A quoi correspond exactement le "OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS" ?

Code:

1
2
3
4
5
6
7
8
9
10
11
********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse   780651     13.09      11.46          3        138          0           0
Execute 780651    270.87     337.93      62476     661420    2080424      298576
Fetch   1000494   1191.574154500164.68     155322    3913556         15      686045
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   2561796   1475.544154500514.08     217801    4575114    2080439      984621

je n'ai pas la main sur le serveur. Avant que je puisse faire de nouvelles demandes de test, je dois avoir une piste sérieuse...

Merci pour votre aide!

20/12/2007, 14h54
orafrance

y'a un problème si un seul core est utilisé... faut quand même se pencher sur ce problème. Quand au elapsed très grand, c'est juste un bug, aucune requête n'a un tel elapsed. Faudrait une trace au moins de niveau 8 pour voir les événements d'attente. Utilises-tu le parallélisme ?
20/12/2007, 15h18
pifor
Est-ce qu'il y d'autres éléments qui ont changé en changeant de machine :
- la version d'Oracle côté serveur ou côté client
- la façon de calculer les statistiques (DBMS_STATS ou ANALYZE)
- des paramètres d'initialisation de l'instance
- le code applicatif côté client
Est-ce que vous pouvez comparer les résultats TKPROF avec les mêmes données et les mêmes requêtes sur les 2 environnements ?

Les chiffres "OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS" correspondent à la somme des temps d'exécutions pour tout le SQL analysé par TKPROF (SQL non récursif = le SQL directement soumis par l'application).

La version oracle au niveau du serveur est la 9.2 sur les 2 environnements.
Je ne sais pas au niveau du client.

La façon de calculer les stats est la même sur les 2 environnements (le calcul des stats est fait régulièrement par l'appli en Delphi)

Qu'entends-tu exactement par paramètres d'initialisation de l'instance ?

Le code applicatif est exactement le même.

Une analyse TKPROF a été fait sur un poste de développement.
Lors des traitements, les traces sont trop grosses (on atteint rapidement plusieurs centaines de mo) pour être complètes. Les traces sont donc désactivées lorsque les fichiers de traces sont importants (800mo à 1go). On n'a donc pas à chaque fois des traces correspondant exactement au même nombre de requêtes.

Ci-dessous le fichier tkprof en environnement de développement. Il n'est pas possible de générer des traces oracle sur le poste qui fonctionne (il est utilisé en production)
Le fetch est plus normal ici.

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
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
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
TKPROF: Release 9.2.0.6.0 - Production on Tue Dec 4 16:53:49 2007
 
Copyright (c) 1982, 2002, Oracle Corporation.  All rights reserved.
 
Trace file: s2008_ora_724.trc
Sort options: prscpu  execpu  fchcpu  
********************************************************************************
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
********************************************************************************
 
EXPLAIN PLAN option disabled.
********************************************************************************
 
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   134977      4.51       4.00          0          0          0           0
Execute 134977    104.08     108.25        146     136589    1520897      134977
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   269954    108.60     112.26        146     136589    1520897      134977
 
Misses in library cache during parse: 1
Misses in library cache during execute: 5
Optimizer goal: CHOOSE
Parsing user id: 25  
 
Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SEQUENCE  
 
********************************************************************************
 
update Dem_Fiche set Traite = :1 
where
 No_Demande_Rff = :2
 
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse    35382      1.16       1.01          0          0          0           0
Execute  35382     73.26      75.94         22     106228     178642       35382
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    70764     74.42      76.95         22     106228     178642       35382
 
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 25  
 
Rows     Row Source Operation
-------  ---------------------------------------------------
      0  UPDATE  
      1   TABLE ACCESS BY INDEX ROWID DEM_FICHE 
      1    INDEX RANGE SCAN IX_DEM_FICHE_03 (object id 6123)
 
********************************************************************************
 
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.01       0.00          0          0          0           0
Execute      5      0.00       0.00          0          0          0           0
Fetch        9     41.36      69.45       7342     137267          0          70
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       19     41.37      69.45       7342     137267          0          70
 
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 25  
 
Rows     Row Source Operation
-------  ---------------------------------------------------
      0  FILTER  
    522   NESTED LOOPS  
   2080    HASH JOIN  
  36006     TABLE ACCESS BY INDEX ROWID REP_PR 
  40946      NESTED LOOPS  
   4939       TABLE ACCESS FULL REP_FICHE 
  36006       INDEX RANGE SCAN IX_REP_PR_01 (object id 6271)
 303507     TABLE ACCESS FULL DEM_PR 
    522    TABLE ACCESS BY INDEX ROWID DEM_FICHE 
   2080     INDEX UNIQUE SCAN PK_DEM_FICHE (object id 6120)
    296   INDEX RANGE SCAN IX_CORRESPONDANCE_02 (object id 6267)
 
********************************************************************************
 
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    39730      1.50       1.50          0          0          0           0
Execute  39730     33.38      36.98        157      41579     537307       39730
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    79460     34.89      38.49        157      41579     537307       39730
 
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 25  
 
Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SEQUENCE  
 
********************************************************************************
 
update dem_fiche set traite=null
 
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0         23          0           0
Execute      1     32.65      35.75          0       4742      88721       43393
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2     32.65      35.75          0       4765      88721       43393
 
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 25  
 
Rows     Row Source Operation
-------  ---------------------------------------------------
      0  UPDATE  
  43393   TABLE ACCESS FULL DEM_FICHE 
 
********************************************************************************
 
UPDATE Dem_Fiche
   SET Etat_Fiche = :1, Date_Modif = :2
 WHERE Id_Fiche_Sncf = :3
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse    15248      0.37       0.43          0          0          0           0
Execute  15248     31.02      32.79         30      45830      46267       15248
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    30496     31.39      33.23         30      45830      46267       15248
 
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer goal: CHOOSE
Parsing user id: 25  
 
Rows     Row Source Operation
-------  ---------------------------------------------------
      0  UPDATE  
      1   TABLE ACCESS BY INDEX ROWID DEM_FICHE 
      1    INDEX RANGE SCAN IX_DEM_FICHE_01 (object id 6121)
 
********************************************************************************
 
select Heure_Local_Arr, Heure_Local_Dep, Ci_Pr
  from Dem_Pr
 where Rang = :1
   and Id_Fiche = :2
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse   169888      5.32       4.99          0          0          0           0
Execute 169888      8.82       8.74          0          0          0           0
Fetch   339776     14.26      22.28        824     849440          0      169888
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   679552     28.41      36.02        824     849440          0      169888
 
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 25  
 
Rows     Row Source Operation
-------  ---------------------------------------------------
      1  TABLE ACCESS BY INDEX ROWID DEM_PR 
      1   INDEX RANGE SCAN IX_DEM_PR_01 (object id 6130)
 
********************************************************************************
 
COMMIT WORK
 
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse   150225      3.48       3.00          0          0          0           0
Execute 150225     22.44      21.53          0          0     150229           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   300450     25.92      24.54          0          0     150229           0
 
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 25  
********************************************************************************
 
UPDATE GRILLE SET NOM_DEMANDEUR = :B10 , NUM_SILLON_DOSSIER = :B16 , 
  NO_DEMANDE_RFF = :B9 , NUM_SILLON_FICHE = :B8 , STATUT_FICHE = :B7 , 
  ETAT_FICHE = :B6 , DATE_RECEPTION_SL = :B5 , DATE_ENVOI_RFF = :B4 , 
  NB_FICHES_TRACES = :B15 , GARE_DEPART = :B3 , HEURE_DEPART = :B14 , 
  GARE_ARRIVEE = :B2 , HEURE_ARRIVEE = :B13 , REGIME_TRADUIT = :B12 , 
  LISTE_TCT = :B1 
WHERE
 ID_FICHE_SNCF = :B11 
 
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse    50631      0.84       0.75          0          0          0           0
Execute  94023     20.81      49.86       1987     189270     101957       94023
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   144654     21.66      50.61       1987     189270     101957       94023
 
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer goal: CHOOSE
Parsing user id: 25     (recursive depth: 1)
 
Rows     Row Source Operation
-------  ---------------------------------------------------
      0  UPDATE  
  43389   INDEX RANGE SCAN IX_GRILLE_02 (object id 6144)
 
 
 
 
********************************************************************************
 
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse   1049999     33.42      30.32          4        150          0           0
Execute 1049999    412.46     579.35      87408    1077735    3821527      576081
Fetch   979722     95.74     726.67      68304    2850371         13      677985
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   3079720    541.63    1336.34     155716    3928256    3821540     1254066
 
Misses in library cache during parse: 61
Misses in library cache during execute: 8
 
 
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse   480345     13.65      12.66          3         46          0           0
Execute 761786     75.39     103.53       2049     368666     515872      276753
Fetch   492696     14.52     110.97      11023    1572630          0      492260
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   1734827    103.57     227.18      13075    1941342     515872      769013
 
Misses in library cache during parse: 128
Misses in library cache during execute: 2
 
1353817  user  SQL statements in session.
176529  internal SQL statements in session.
1530346  SQL statements in session.
    0  statements EXPLAINed in this session.
********************************************************************************
Trace file: s2008_ora_724.trc
Trace file compatibility: 9.02.00
Sort options: prscpu  execpu  fchcpu  
       1  session in tracefile.
  1353817  user  SQL statements in trace file.
  176529  internal SQL statements in trace file.
  1530346  SQL statements in trace file.
     185  unique SQL statements in trace file.
 18777181  lines in trace file.

20/12/2007, 17h53
13thFloor

Un petit report de statspack serait utile.
Coté RAM, le nouveau serveur a t-il une quantité >= à l'ancien ?
Tout est fait sur le serveur ? Il n'y a pas une sonde ou un antivirus entre le poste client et le serveur qui ralentirait le traffic de data ?
20/12/2007, 17h57
pifor

Les paramètres d'initialisation = le contenu du fichier init.ora (pfile ou spfile).

On voit que votre environnement de développement n'a pas les mêmes données (il y a beaucoup moins de lignes dans les tables).

Il faudrait essayer de faire sauter la limitation sur le fichier trace sinon on ne peut pas même pas être sûr d'avoir les requêtes les plus lourdes. Et comme déjà demandé, il faudrait avoir les waits.

Concernant la ram, il y a sur les 2 serveurs 1GO.

(le passage à 2Go de ram ne serait pas superflu)

Cela me parait difficile de ne pas arrêter les traces oracle avant la fin, sinon cela prendra trop de place.

L'antivirus a été désactivé.
On m'a fourni plusieurs captures d'écran du gestionnaire des tâches pendant la durée des traitements, le processus oracle est celui qui utilise le plus le CPU. Ensuite l'application en delphi est la 2ème plus gourmande. Cependant, le CPU est en dessous de 50%.

Je vais essayer de récupérer le fichier init.ora demain...
Pour avoir les waits, quelle est la méthode la plus simple?

Merci

Ci-dessous une liste de paramètres oracle (identiques sur les 2 plateformes) Il y a aussi le GETHITRATIO du nouveau serveur (plus élevé que l'autre serveur en prod actuellement)
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 NAME TYPE VALUE ------------------------------------ ----------- ------------------------------ sga_max_size big integer 328016000 NAME TYPE VALUE ------------------------------------ ----------- ------------------------------ shared_pool_size big integer 16777216 NAME TYPE VALUE ------------------------------------ ----------- ------------------------------ shared_pool_reserved_size big integer 838860 NAME TYPE VALUE ------------------------------------ ----------- ------------------------------ sort_area_size integer 65536 NAME TYPE VALUE ------------------------------------ ----------- ------------------------------ db_cache_size big integer 293601280 NAME TYPE VALUE ------------------------------------ ----------- ------------------------------ db_block_size integer 8192 NAME TYPE VALUE ------------------------------------ ----------- ------------------------------ optimizer_features_enable string 9.2.0 NAME TYPE VALUE ------------------------------------ ----------- ------------------------------ pga_aggregate_target big integer 83886080 SELECT gethitratio FROM v$librarycache WHERE namespace = 'SQL AREA'; GETHITRATIO ----------- ,898646035

20/12/2007, 18h29
orafrance

et la volumétrie est la même ? T'es sûr que l'OS ne swappe pas ?
20/12/2007, 19h48
LeoAnderson

y'a un truc qui m'échappe : dans le tkprof, la somme n'a rien à voir avec le détail... 8O

Soit il manque des requêtes, soit le TKProf n'est pas de confiance....
Dans tous les cas, on n'a pas les billes....:oops:
20/12/2007, 22h58
matd53

j'avais enlevé certaines parties du premier résultat tkprof (nouveau serveur) , mais le 2ème est bien complet (serveur de développement).
21/12/2007, 00h22
matd53

Au niveau de la volumétrie des données en base, c'est sûr qu'elle n'est pas plus importante sur le nouveau serveur par rapport à l'ancien qui fonctionne correctement pour une configuration matérielle inférieure...

Concernant le swap de l'OS, je ne peux pas le dire de façon certaine. Je viens de lire cette page http://shsc.info/WindowsMemoryManagement qui m'a appris qu'il n'est pas facile de savoir s'il manque de la mémoire ou non.
J'ai les captures suivantes du task manager pendant le traitement (malheureusement je n'ai pas l'onglet performance, bien que je l'avais demandé à la personne qui a fait les captures...)
On voit en bas la quantité de mémoire utilisée 1833992K / 3094716K (le serveur a 1go de RAM)
Il y a pas mal de page faults, mais étant donné le grand nombre de lecture/écriture, je ne suis pas sûr que cela soit choquant.
http://img406.imageshack.us/img406/1141/66zw0.jpg
http://img88.imageshack.us/img88/237/72th1.jpg

Gestion_Sillons c'est l'application en Delphi qui entre autre exécute les requêtes.
21/12/2007, 07h56
LeoAnderson

Citation:

Envoyé par matd53

j'avais enlevé certaines parties du premier résultat tkprof (nouveau serveur) , mais le 2ème est bien complet (serveur de développement).

oui, mais s'il ne représente pas ce qui se passe là où il y a le problème...

je comprends que c'est pas jouable d'uploader 800 Mo mais va falloir trouver quelque chose pour qu'on ait les infos !!

par contre, les 140 000 fautes de pages sur le process Oracle, c'est pas top...
http://www.developpez.net/forums/sho...d.php?t=155205

==> Il swap...
21/12/2007, 08h54
orafrance

1.8G de mémoire utilisée alors que tu as 1Go de RAM... on peut donc penser que ça swappe :?

Ensuite, faudrait trouver la requête qui prend le plus de temps et vérifier que le plan est le même sur les 2 instances.
21/12/2007, 09h11
LeoAnderson

le hit ratio est comment ?

si le hit ratio est bon, comme il swap, ça veut dire qu'Oracle croit avoir plus de mémoire qu'il n'en a réellement => baisser la SGA
si le hit ratio est mauvais, Oracle demande des lectures physiques et donc, on ne devrait pas avoit de fautes de pages.
21/12/2007, 09h48
matd53

Le Hit Ratio est de 0,898646035 sur le nouveau serveur qui a des pbs de performances.
Le SGA_max_size est de 328014848. Est-ce que cette valeur est trop importante?

Les temps d'exécution des requêtes ne sont pas importants par rapport à la durée totale du traitement. Je ne vois donc pas trop l'intérêt d'aller plus loin dans l'analyse de leurs plans d'exécution.

Seul le elapsed time des fetch pour l'"OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS" est vraiment étonnant...

Le résultat complet du rapport TKPROF des traces générées (800mo de traces analysées avec TKPROF qui ne représentent qu'une partie du traitement), est trop long pour l'afficher entièrement sur cette page...

Les logs applicatifs montrent que c'est tout le traitement qui est plus long que la normale et pas une partie en particulier.

Merci pour l'aide que vous m'avez déjà apporté!
21/12/2007, 10h05
orafrance

un SGA_MAX_SIZE de 300Mo c'est pas délirant mais faut voir ce qui est sur le serveur parce que là visiblement ça swape... et si tu avais bien voulu faire une trace de level 8 tu pourrais probablement voir des waits sur les I/O :roll:

Je viens de voir dans le fichier tkprof des traces du nouveau serveur la requête suivante que j'avais enlevé dans la partie affichée sur le forum :oops: et qui a un fetch énorme (mais un temps CPU très faible):

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
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)

Votre analyse la dessus? Un bug de tkprof?

21/12/2007, 10h08
LeoAnderson

pouvez-vous uploader le zip de la trace avant tkprof concernant simplement cette requête ?
21/12/2007, 10h08
matd53

Pour l'analyse level 8, je vais essayer d'en obtenir une. Cependant ça ne va pas être possible rapidement... (vacances oblige...)
21/12/2007, 10h22
matd53

Citation:

Envoyé par LeoAnderson

pouvez-vous uploader le zip de la trace avant tkprof concernant simplement cette requête ?

Je ne comprends pas comment faire cela?
Comment isoler cette requête appelée de nombreuses fois du fichier de traces?

Voir 40 message(s) de cette discussion en une page