[10.2.0.1 sur W2K3] interprétation rapport TKPROF

fred_04510 · 08/12/2010, 09h00

Bonjour,
J'ai généré un rapport TKPROF (Waits=y sort=exeela,fchela,prsela) à partir d'une trace de session (durée=2-3 minutes).
Dans la rubrique "Elapsed times include waiting on following events" je vois un Total Waited important mais je ne retrouve ce temps important dans aucun ordre sql analysé.

Est ce que mon problème de performance est bien lié aux wait events ?
Si oui comment mettre à profit mon rapport TKPROF pour résoudre ce problème?

Merci d'avance,

Frédéric

Ci joint le rapport TKPROF :

Code :

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

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
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
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
455
456
457
458
459
460
461
462
463
464
465
466
467
468
469
470
471
472
473
474
475
476
477
478
479
480
481
482
483
484
485
486
487
488
489
490
491
492
493
494
495
496
497
498
499
500
501
502
503
504
505
506
507
508
509
510
511
512
513
514
515
516
517
518
519
520
521
522
523
524
525
526
527
528
529
530
531
532
533
534
535
536
537
538
539
540
541
542
543
544
545
546
547
548
549
550
551
552
553
554
555
556
557
558
559
560
561
562
563
564
565
566
567
568
569
570
571
572
573
574
575
576
577
578
579
580
581
582
583
584
585
586
587
588
589
590
591
592
593
594
595
596
597
598
599
600
601
602
603
604
605
606
607
608
609
610
611
612
613
614
615
616
617
618
619
620
621
622
623
624
625
626
627
628
629
630
631
632
633
634
635
636
637
638
639
640
641
642
643
644
 
 
 
TKPROF: Release 10.2.0.1.0 - Production ON Mer. Déc. 8 08:35:55 2010
 
Copyright (c) 1982, 2005, Oracle.  ALL rights reserved.
 
Trace file: pam_ora_1772.trc
Sort options: exeela  fchela  prsela  
********************************************************************************
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 obd1.otProperty1  ,obd1.otProperty2  ,obd1.odDateHandled  + 0.04167 AS 
  odDateHandled ,obd1.omComment  ,obd1.omSoluce  ,obd1.oidEquipment  ,
  obd1.oidType  ,obd1.oidCategory  ,obd1.oidCaller  ,obd1.oidCreator  ,
  obd1.oidResponsable  ,obd1.oidUser  ,obd1.omDescription  ,obd1.oidUrgency  ,
  obd1.oidImpact  ,obd1.odDateEndDue  + 0.04167 AS odDateEndDue ,
  obd1.oidIntervener  ,obd1.odDateEndEntryDue  + 0.04167 AS odDateEndEntryDue 
  ,obd1.onlLengthDue  ,obd1.onlLength  ,obd1.odDate1  + 0.04167 AS odDate1 ,
  obd1.odDate2  + 0.04167 AS odDate2 ,obd1.odDateOpen  + 0.04167 AS 
  odDateOpen ,obd1.odDateClose  + 0.04167 AS odDateClose ,obd1.oidOrigin  ,
  obd1.otText1  ,obd1.oidPriority  ,obd1.otText2  ,obd1.otText3  ,
  obd1.onlLong1  ,obd1.onlLength1  ,obd1.onlLengthDue1  ,
  obd1.odDateEndOpenDue  + 0.04167 AS odDateEndOpenDue ,
  obd1.odDateEndResolvedDue  + 0.04167 AS odDateEndResolvedDue ,
  obd1.odDateEndDue1  + 0.04167 AS odDateEndDue1 ,obd1.onlLengthEntry  ,
  obd1.onlLengthOpen  ,obd1.onlLengthResolved  ,obd1.onlLengthClose  ,
  obd1.otList1  ,obd1.otList2  ,obd1.onlLength2  ,obd1.onlLengthDue2 
FROM
 otIncident obd1,(SELECT DISTINCT oidObject FROM OTX119212SDesk) obd2 WHERE 
  obd1.oidobject = obd2.oidObject ORDER BY obd2.oidObject
 
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          3          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       67      0.23       0.42        523        457          3        6688
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       69      0.23       0.43        523        460          3        6688
 
Misses IN library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 117  
 
Elapsed times include waiting ON following events:
  Event waited ON                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message TO client                      68        0.00          0.00
  SQL*Net more DATA TO client                  1679        0.02          0.19
  SQL*Net message FROM client                    68        0.00          0.07
  direct path WRITE temp                         31        0.00          0.03
  direct path READ temp                          98        0.00          0.01
********************************************************************************
 
INSERT /*+ APPEND */ INTO OTX119212SDesk(oidObject,oidObjectType,
  oidObjectFather,oidArticle,oniLevel) SELECT /*+ INDEX(obr2 
  ZIDXOIDOBJECTTYPE46) */   ob.oidObject,ob.oidObjectType,ob.oidObjectFather,
  ob.oidArticle,1 AS oniLevel FROM PAM.OVP272179941 ob,otObjectRelation obr2 
  WHERE ob.oidobject =obr2.oidObject AND ob.oidObjectType IN(3004) AND 
  obr2.oidObjectType IN(3004) AND obr2.oidAxis = 0 AND 
  (obr2.oidObjectRelationType = 301)
 
 
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.20       0.20          0       8487        860        6688
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.20       0.20          0       8487        860        6688
 
Misses IN library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 117  
 
Rows     Row Source Operation
-------  ---------------------------------------------------
   6688  HASH JOIN  (cr=8335 pr=0 pw=0 time=343965 us)
   6688   TABLE ACCESS BY INDEX ROWID OTOBJECTRELATION (cr=746 pr=0 pw=0 time=93690 us)
   6688    INDEX RANGE SCAN ZIDXOIDOBJECTTYPE46 (cr=29 pr=0 pw=0 time=20748 us)(object id 73585)
   6688   NESTED LOOPS  (cr=7589 pr=0 pw=0 time=214906 us)
   6688    TABLE ACCESS FULL OTOBJECT (cr=899 pr=0 pw=0 time=33875 us)
   6688    INDEX UNIQUE SCAN ZIDXOTP272179941 (cr=6690 pr=0 pw=0 time=91569 us)(object id 108616)
 
 
Elapsed times include waiting ON following events:
  Event waited ON                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  log file sync                                   1        0.00          0.00
  SQL*Net message TO client                       1        0.00          0.00
  SQL*Net message FROM client                     1        0.00          0.00
********************************************************************************
 
SELECT obd1.otModel  ,obd1.otInternalNumber  ,obd1.otStatus  ,obd1.otField1  ,
  obd1.oidObject  ,obd1.odDateScan  + 0.04167 AS odDateScan ,obd1.odDateEntry 
   + 0.04167 AS odDateEntry 
FROM
 otObject obd1,(SELECT DISTINCT oidObject FROM OTX119212SDesk) obd2 WHERE 
  obd1.oidobject = obd2.oidObject AND obd1.oidObjectType = 3004 ORDER BY 
  obd2.oidObject
 
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          3          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       67      0.07       0.05          0        931          0        6688
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       69      0.07       0.05          0        934          0        6688
 
Misses IN library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 117  
 
Rows     Row Source Operation
-------  ---------------------------------------------------
   6688  SORT ORDER BY (cr=931 pr=0 pw=0 time=52766 us)
   6688   HASH JOIN  (cr=931 pr=0 pw=0 time=167103 us)
   6688    VIEW  (cr=32 pr=0 pw=0 time=53535 us)
   6688     INDEX FAST FULL SCAN SYS_C005213944 (cr=32 pr=0 pw=0 time=20089 us)(object id 2806570)
   6688    TABLE ACCESS FULL OTOBJECT (cr=899 pr=0 pw=0 time=27220 us)
 
 
Elapsed times include waiting ON following events:
  Event waited ON                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message TO client                      67        0.00          0.00
  SQL*Net more DATA TO client                   202        0.00          0.00
  SQL*Net message FROM client                    67        0.46          0.55
********************************************************************************
 
SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE 
  NO_PARALLEL(SAMPLESUB) opt_param('parallel_execution_enabled', 'false') 
  NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_0"), 
  NVL(SUM(C2),:"SYS_B_1") 
FROM
 (SELECT /*+ NO_PARALLEL("OTX119212SDESK") FULL("OTX119212SDESK") 
  NO_PARALLEL_INDEX("OTX119212SDESK") */ :"SYS_B_2" AS C1, :"SYS_B_3" AS C2 
  FROM "OTX119212SDESK" "OTX119212SDESK") SAMPLESUB
 
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        6      0.00       0.00          0          0          0           0
Execute      6      0.01       0.00          0          0          0           0
Fetch        6      0.00       0.00          0        187          0           6
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       18      0.01       0.01          0        187          0           6
 
Misses IN library cache during parse: 1
Misses IN library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 117     (recursive depth: 1)
 
Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT AGGREGATE (cr=52 pr=0 pw=0 time=2993 us)
   6688   TABLE ACCESS FULL OTX119212SDESK (cr=52 pr=0 pw=0 time=20136 us)
 
********************************************************************************
 
SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE 
  NO_PARALLEL(SAMPLESUB) opt_param('parallel_execution_enabled', 'false') 
  NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_0"), 
  NVL(SUM(C2),:"SYS_B_1"), COUNT(DISTINCT C3), NVL(SUM(CASE WHEN C3 IS NULL 
  THEN :"SYS_B_2" ELSE :"SYS_B_3" END),:"SYS_B_4") 
FROM
 (SELECT /*+ NO_PARALLEL("OTX119212SDESK") FULL("OTX119212SDESK") 
  NO_PARALLEL_INDEX("OTX119212SDESK") */ :"SYS_B_5" AS C1, :"SYS_B_6" AS C2, 
  "OTX119212SDESK"."OIDOBJECT" AS C3 FROM "OTX119212SDESK" "OTX119212SDESK") 
  SAMPLESUB
 
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      0.01       0.00          0         27          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.01       0.01          0         27          0           1
 
Misses IN library cache during parse: 1
Misses IN library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 117     (recursive depth: 1)
 
Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT GROUP BY (cr=27 pr=0 pw=0 time=8381 us)
   6688   TABLE ACCESS FULL OTX119212SDESK (cr=27 pr=0 pw=0 time=66896 us)
 
********************************************************************************
 
SELECT count(*) 
FROM
 user_policies o WHERE  o.object_name = :tablename  AND (policy_name LIKE 
  '%xdbrls%' OR policy_name LIKE '%$xd_%') AND o.FUNCTION=
  'CHECKPRIVRLS_SELECTPF'
 
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      0.00       0.00          0         23          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.00       0.00          0         23          0           1
 
Misses IN library cache during parse: 0
Misses IN library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 117     (recursive depth: 2)
 
Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT AGGREGATE (cr=23 pr=0 pw=0 time=401 us)
      0   NESTED LOOPS  (cr=23 pr=0 pw=0 time=375 us)
      8    NESTED LOOPS  (cr=5 pr=0 pw=0 time=163 us)
      1     TABLE ACCESS BY INDEX ROWID USER$ (cr=2 pr=0 pw=0 time=50 us)
      1      INDEX UNIQUE SCAN I_USER1 (cr=1 pr=0 pw=0 time=28 us)(object id 44)
      8     TABLE ACCESS FULL RLS$ (cr=3 pr=0 pw=0 time=68 us)
      0    TABLE ACCESS BY INDEX ROWID OBJ$ (cr=18 pr=0 pw=0 time=215 us)
      8     INDEX UNIQUE SCAN I_OBJ1 (cr=10 pr=0 pw=0 time=106 us)(object id 36)
 
********************************************************************************
 
TRUNCATE TABLE OTX119212SDesk
 
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          2           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          2           0
 
Misses IN library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 117  
 
Elapsed times include waiting ON following events:
  Event waited ON                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  log file sync                                   1        0.06          0.06
  SQL*Net message TO client                       1        0.00          0.00
  SQL*Net message FROM client                     1        0.00          0.00
********************************************************************************
 
BEGIN
  BEGIN
    IF (xdb.DBMS_XDBZ0.is_hierarchy_enabled_internal(sys.dictionary_obj_owner, sys.dictionary_obj_name, sys.dictionary_obj_owner)) THEN
      xdb.XDB_PITRIG_PKG.pitrig_truncate(sys.dictionary_obj_owner, sys.dictionary_obj_name);
    END IF;
  EXCEPTION
    WHEN OTHERS THEN
     NULL;
  END;
  BEGIN
    IF (xdb.DBMS_XDBZ0.is_hierarchy_enabled_internal(sys.dictionary_obj_owner, sys.dictionary_obj_name, sys.dictionary_obj_owner, xdb.DBMS_XDBZ.IS_ENABLED_RESMETADATA)) THEN
      xdb.XDB_PITRIG_PKG.pitrig_dropmetadata(sys.dictionary_obj_owner, sys.dictionary_obj_name);
    END IF;
  EXCEPTION
    WHEN OTHERS THEN
     NULL;
  END;
END;
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.01       0.00          0          0          0           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.01       0.00          0          0          0           1
 
Misses IN library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 33     (recursive depth: 1)
********************************************************************************
 
SELECT /*+ ALL_ROWS */ COUNT(*) 
FROM
 ALL_POLICIES V WHERE V.OBJECT_OWNER = :B3 AND V.OBJECT_NAME = :B2 AND 
  (POLICY_NAME LIKE '%xdbrls%' OR POLICY_NAME LIKE '%$xd_%') AND V.FUNCTION = 
  :B1 
 
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch        2      0.01       0.00          0        108          0           2
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.01       0.00          0        108          0           2
 
Misses IN library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 33     (recursive depth: 2)
********************************************************************************
 
SELECT o.owner#, u.name,        o.name,            o.namespace,    o.obj#,   
  d.d_timestamp, nvl(d.property,0), o.type#, o.subname, d.d_attrs  
FROM
 dependency$ d, obj$ o, user$ u  WHERE d.p_obj#=:1  and   (d.p_timestamp=:2 
  OR d.property=2)  AND   d.d_obj#=o.obj#  and   o.owner#=u.user#  order by 
  o.obj#
 
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.00          0          0          0           0
Execute      2      0.01       0.00          0          0          0           0
Fetch        2      0.00       0.00          0          6          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        6      0.01       0.00          0          6          0           0
 
Misses IN library cache during parse: 1
Misses IN library cache during execute: 1
Optimizer mode: CHOOSE
Parsing user id: SYS   (recursive depth: 1)
 
Rows     Row Source Operation
-------  ---------------------------------------------------
      0  SORT ORDER BY (cr=3 pr=0 pw=0 time=110 us)
      0   NESTED LOOPS  (cr=3 pr=0 pw=0 time=84 us)
      0    NESTED LOOPS  (cr=3 pr=0 pw=0 time=73 us)
      0     TABLE ACCESS BY INDEX ROWID DEPENDENCY$ (cr=3 pr=0 pw=0 time=64 us)
      0      INDEX RANGE SCAN I_DEPENDENCY2 (cr=3 pr=0 pw=0 time=37 us)(object id 123)
      0     TABLE ACCESS BY INDEX ROWID OBJ$ (cr=0 pr=0 pw=0 time=0 us)
      0      INDEX UNIQUE SCAN I_OBJ1 (cr=0 pr=0 pw=0 time=0 us)(object id 36)
      0    TABLE ACCESS CLUSTER USER$ (cr=0 pr=0 pw=0 time=0 us)
      0     INDEX UNIQUE SCAN I_USER# (cr=0 pr=0 pw=0 time=0 us)(object id 11)
 
********************************************************************************
 
SELECT text 
FROM
 VIEW$ WHERE rowid=:1
 
 
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        5      0.00       0.00          0         10          0           5
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       15      0.00       0.00          0         10          0           5
 
Misses IN library cache during parse: 1
Misses IN library cache during execute: 1
Optimizer mode: CHOOSE
Parsing user id: SYS   (recursive depth: 3)
 
Rows     Row Source Operation
-------  ---------------------------------------------------
      1  TABLE ACCESS BY USER ROWID VIEW$ (cr=1 pr=0 pw=0 time=24 us)
 
********************************************************************************
 
SELECT count(*) 
FROM
 user_policies o WHERE  o.object_name = :tablename  AND (policy_name LIKE 
  '%xdbrls%' OR policy_name LIKE '%$xd_%') AND o.FUNCTION=
  'CHECKPRIVRLS_SELECTPROPF'
 
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      0.00       0.00          0          5          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.00       0.00          0          5          0           1
 
Misses IN library cache during parse: 0
Misses IN library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 117     (recursive depth: 2)
 
Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT AGGREGATE (cr=5 pr=0 pw=0 time=121 us)
      0   NESTED LOOPS  (cr=5 pr=0 pw=0 time=100 us)
      0    NESTED LOOPS  (cr=5 pr=0 pw=0 time=89 us)
      1     TABLE ACCESS BY INDEX ROWID USER$ (cr=2 pr=0 pw=0 time=43 us)
      1      INDEX UNIQUE SCAN I_USER1 (cr=1 pr=0 pw=0 time=23 us)(object id 44)
      0     TABLE ACCESS FULL RLS$ (cr=3 pr=0 pw=0 time=31 us)
      0    TABLE ACCESS BY INDEX ROWID OBJ$ (cr=0 pr=0 pw=0 time=0 us)
      0     INDEX UNIQUE SCAN I_OBJ1 (cr=0 pr=0 pw=0 time=0 us)(object id 36)
 
********************************************************************************
 
SELECT n.intcol# 
FROM
 ntab$ n, col$ c  WHERE n.obj#=:1 and c.obj#=:1 and c.intcol#=n.intcol# and 
  bitand(c.property, 32768)!=32768
 
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.00          0          0          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          0         20          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        6      0.00       0.00          0         20          0           0
 
Misses IN library cache during parse: 1
Misses IN library cache during execute: 1
Optimizer mode: CHOOSE
Parsing user id: SYS   (recursive depth: 1)
 
Rows     Row Source Operation
-------  ---------------------------------------------------
      0  NESTED LOOPS  (cr=10 pr=0 pw=0 time=141 us)
      5   TABLE ACCESS CLUSTER COL$ (cr=8 pr=0 pw=0 time=70 us)
      1    INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=0 pw=0 time=18 us)(object id 3)
      0   INDEX UNIQUE SCAN I_NTAB2 (cr=2 pr=0 pw=0 time=45 us)(object id 200)
 
********************************************************************************
 
SELECT COUNT(*)  
FROM
 OTX119212SDesk 
 
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          1          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      0.00       0.00          0         59          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.00       0.00          0         60          0           1
 
Misses IN library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 117  
 
Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT AGGREGATE (cr=59 pr=0 pw=0 time=1450 us)
   6688   INDEX FAST FULL SCAN SYS_C005213944 (cr=59 pr=0 pw=0 time=20102 us)(object id 2806570)
 
 
Elapsed times include waiting ON following events:
  Event waited ON                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message TO client                       1        0.00          0.00
  SQL*Net message FROM client                     1        0.00          0.00
********************************************************************************
 
SELECT otObjectType.otName  
FROM
 otObjectType WHERE  oidObjectType IN(3004) 
 
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      0.00       0.00          0          2          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.00       0.00          0          2          0           1
 
Misses IN library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 117  
 
Rows     Row Source Operation
-------  ---------------------------------------------------
      1  TABLE ACCESS BY INDEX ROWID OTOBJECTTYPE (cr=2 pr=0 pw=0 time=59 us)
      1   INDEX UNIQUE SCAN SYS_C00106508 (cr=1 pr=0 pw=0 time=31 us)(object id 73596)
 
 
Elapsed times include waiting ON following events:
  Event waited ON                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message TO client                       1        0.00          0.00
  SQL*Net message FROM client                     1        0.03          0.03
********************************************************************************
 
SELECT log, sysdate, sysdate+1/86400, flag 
FROM
 sys.mlog$   WHERE  mowner = :1 AND master = :2 FOR UPDATE
 
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          1          0           0
Fetch        1      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.00       0.00          0          1          0           0
 
Misses IN library cache during parse: 1
Misses IN library cache during execute: 1
Optimizer mode: CHOOSE
Parsing user id: SYS   (recursive depth: 1)
 
Rows     Row Source Operation
-------  ---------------------------------------------------
      0  FOR UPDATE  (cr=1 pr=0 pw=0 time=34 us)
      0   TABLE ACCESS CLUSTER MLOG$ (cr=1 pr=0 pw=0 time=22 us)
      0    INDEX UNIQUE SCAN I_MLOG# (cr=1 pr=0 pw=0 time=10 us)(object id 164)
 
********************************************************************************
 
SELECT 1 
FROM
 sys.cdc_change_tables$  WHERE source_schema_name = :1  AND source_table_name 
  = :2  AND bitand(mvl_flag, 128)=128
 
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      0.00       0.00          0          3          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.00       0.00          0          3          0           0
 
Misses IN library cache during parse: 1
Misses IN library cache during execute: 1
Optimizer mode: CHOOSE
Parsing user id: SYS   (recursive depth: 1)
 
Rows     Row Source Operation
-------  ---------------------------------------------------
      0  TABLE ACCESS FULL CDC_CHANGE_TABLES$ (cr=3 pr=0 pw=0 time=22 us)
 
********************************************************************************
 
SELECT USER_ID 
FROM
 ALL_USERS WHERE USERNAME = :B1 
 
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          0         14          0           2
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          0         14          0           2
 
Misses IN library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 33     (recursive depth: 2)
********************************************************************************
 
SELECT oidobjectType  
FROM
 otObjectDependance WHERE  (oidObjectDependance = 301 AND onimin >= 1 AND 
  oidobjectType IN(3004) AND oidAxis=0) 
 
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      0.00       0.00          0          3          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.00       0.00          0          3          0           1
 
Misses IN library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 117  
 
Rows     Row Source Operation
-------  ---------------------------------------------------
      1  TABLE ACCESS BY INDEX ROWID OTOBJECTDEPENDANCE (cr=3 pr=0 pw=0 time=59 us)
      1   INDEX UNIQUE SCAN SYS_C00106475 (cr=2 pr=0 pw=0 time=27 us)(object id 73556)
 
 
Elapsed times include waiting ON following events:
  Event waited ON                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message TO client                       1        0.00          0.00
  SQL*Net message FROM client                     1        0.00          0.00
 
 
 
********************************************************************************
 
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        7      0.00       0.02          0          7          0           0
Execute      7      0.20       0.20          0       8487        862        6688
Fetch      137      0.31       0.47        523       1452          3       13379
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      151      0.51       0.70        523       9946        865       20067
 
Misses IN library cache during parse: 7
 
Elapsed times include waiting ON following events:
  Event waited ON                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message FROM client                 22190      115.20        126.39
  SQL*Net message TO client                   22190        0.00          0.04
  log file sync                                   2        0.06          0.07
  SQL*Net more DATA TO client                  1920        0.02          0.20
  direct path WRITE temp                         31        0.00          0.03
  direct path READ temp                          98        0.00          0.01
  SQL*Net more DATA FROM client                   9        0.00          0.00
 
 
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       21      0.00       0.00          0          0          0           0
Execute     25      0.04       0.03          0          1          0           1
Fetch       24      0.03       0.02          0        403          0          18
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       70      0.07       0.06          0        404          0          19
 
Misses IN library cache during parse: 7
Misses IN library cache during execute: 9
 
   19  user  SQL statements IN session.
   11  internal SQL statements IN session.
   30  SQL statements IN session.
********************************************************************************
Trace file: pam_ora_1772.trc
Trace file compatibility: 10.01.00
Sort options: exeela  fchela  prsela  
       1  session IN tracefile.
      19  user  SQL statements IN trace file.
      11  internal SQL statements IN trace file.
      30  SQL statements IN trace file.
      19  UNIQUE SQL statements IN trace file.
   47252  LINES IN trace file.
      13  elapsed seconds IN trace file.

Rams7s · 08/12/2010, 11h59

Bonjour,

Il y a effectivement un temps d'attente relativement important de 126 secondes. Apres, est-ce que c'est normal? La base attend quand meme 22 190 fois un message du client. C'est pas parce que la base attend qu'il y a forcement un probleme de performance. Ou du moins, il n'est pas forcement lie a la base.

Exemple:
Soit le script suivant:

Code :

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

1
2
3
4
5
6
7
8
9
10
11
12
 
ALTER session SET events '10046 trace name context forever, level 12';
SELECT * FROM emp;
exec dbms_lock.sleep(5);
SELECT * FROM emp;
exec dbms_lock.sleep(1);
SELECT * FROM emp;
exec dbms_lock.sleep(1);
SELECT * FROM emp;
exec dbms_lock.sleep(1);
SELECT * FROM emp;
ALTER session SET events '10046 trace name context off';

On regarde la trace tkprof:

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
 
 
********************************************************************************
 
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
 
Elapsed times include waiting ON following events:
  Event waited ON                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message TO client                      20        0.00          0.00
  SQL*Net message FROM client                    20        0.27          1.06
  db file sequential READ                         1        0.23          0.23
  Disk file operations I/O                        2        0.00          0.00
  db file scattered READ                          1        0.03          0.03
  PL/SQL LOCK timer                               4        4.99          8.02

Ici encore, on a un temps d'attente relativement important, de 8 secondes en tout et pour tout pour le PL/SQL. C'est normal, on a mis des sleeps dans le code. Par contre, ce qui ralentit le plus c'est quoi ?
Qu'on ait attendu 4 fois, ou bien qu'une fois sur ces 4 fois on ait attendu 5 secondes? Le temps d'attente de 5 secondes, clairement si on le reduit a une seconde on va nettement ameliorer les performances du script.

Dans votre cas, c'est pareil:

Code :

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

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
 
********************************************************************************
 
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        7      0.00       0.02          0          7          0           0
Execute      7      0.20       0.20          0       8487        862        6688
Fetch      137      0.31       0.47        523       1452          3       13379
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      151      0.51       0.70        523       9946        865       20067
 
Misses IN library cache during parse: 7
 
Elapsed times include waiting ON following events:
  Event waited ON                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message FROM client                 22190      115.20        126.39
  SQL*Net message TO client                   22190        0.00          0.04
  log file sync                                   2        0.06          0.07
  SQL*Net more DATA TO client                  1920        0.02          0.20
  direct path WRITE temp                         31        0.00          0.03
  direct path READ temp                          98        0.00          0.01
  SQL*Net more DATA FROM client                   9        0.00          0.00
 
 
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       21      0.00       0.00          0          0          0           0
Execute     25      0.04       0.03          0          1          0           1
Fetch       24      0.03       0.02          0        403          0          18
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       70      0.07       0.06          0        404          0          19

Oracle passe la majorite de son temps a attendre des trucs a faire.Des qu'elle peut travailler, elle le fait tres vite, c'est pas le soucis.
En revanche, elle attends souvent des ordres, et renvoie tout aussi souvent des resultats (22 190 pour les deux). Mais, ce qui a vraiment pris le plus de temps, c'est un temps de 115s entre deux requetes.

Alors apres, a savoir si c'est normal, c'est votre systeme.

Mais si on la laisse sans rien lui demander pendant 2 minutes, ce serait justement anormal que la base travaille. En revanche, si c'est anormal, il faut voir avec les logiciels qui utilisent la base de donnees.

fred_04510 · 08/12/2010, 12h05

Merci,
Donc le rapport TKPROF ne met pas en évidence d'autre problème qu'un problème du au client (ou a la communication avec le client)?

Frédéric.

08/12/2010, 12h05	#3
fred_04510 Membre du Club Inscription : avril 2009 Messages : 192 Détails du profil Informations forums : Inscription : avril 2009 Messages : 192 Points : 66 Points : 66	Merci, Donc le rapport TKPROF ne met pas en évidence d'autre problème qu'un problème du au client (ou a la communication avec le client)? Frédéric.
	00

Outils de la discussion
Afficher une version imprimable Envoyer un lien vers cette page par email