IdentifiantMot de passe
Loading...
Mot de passe oublié ?Je m'inscris ! (gratuit)
Navigation

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

Administration Oracle Discussion :

[10.2.0.1 sur W2K3] interprétation rapport TKPROF


Sujet :

Administration Oracle

  1. #1
    Membre régulier
    Profil pro
    Inscrit en
    Avril 2009
    Messages
    217
    Détails du profil
    Informations personnelles :
    Localisation : France

    Informations forums :
    Inscription : Avril 2009
    Messages : 217
    Points : 112
    Points
    112
    Par défaut [10.2.0.1 sur W2K3] interprétation rapport TKPROF
    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.

  2. #2
    Membre éclairé
    Profil pro
    Inscrit en
    Février 2010
    Messages
    412
    Détails du profil
    Informations personnelles :
    Localisation : France

    Informations forums :
    Inscription : Février 2010
    Messages : 412
    Points : 807
    Points
    807
    Par défaut
    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.

  3. #3
    Membre régulier
    Profil pro
    Inscrit en
    Avril 2009
    Messages
    217
    Détails du profil
    Informations personnelles :
    Localisation : France

    Informations forums :
    Inscription : Avril 2009
    Messages : 217
    Points : 112
    Points
    112
    Par défaut
    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.

Discussions similaires

  1. [PB 7.0.3] Deux requêtes sur le même rapport
    Par aigle_ma dans le forum Powerbuilder
    Réponses: 4
    Dernier message: 05/07/2007, 16h37
  2. reporting services 2 tableaux alternés sur un même rapport
    Par ironice dans le forum MS SQL Server
    Réponses: 1
    Dernier message: 25/06/2007, 14h53
  3. Comment l'environnement influe t'il sur l'interprétation CSS ?
    Par Sunsawe dans le forum Mise en page CSS
    Réponses: 4
    Dernier message: 15/03/2007, 08h21
  4. 2 requêtes indépendantes sur un seul rapport
    Par doudou.thedude dans le forum SAP Crystal Reports
    Réponses: 6
    Dernier message: 02/02/2007, 15h12
  5. Trojan win32 : interprétation rapport HijackThis
    Par vdmvdm dans le forum Sécurité
    Réponses: 11
    Dernier message: 23/08/2006, 11h38

Partager

Partager
  • Envoyer la discussion sur Viadeo
  • Envoyer la discussion sur Twitter
  • Envoyer la discussion sur Google
  • Envoyer la discussion sur Facebook
  • Envoyer la discussion sur Digg
  • Envoyer la discussion sur Delicious
  • Envoyer la discussion sur MySpace
  • Envoyer la discussion sur Yahoo