This discussion is archived
13 Replies Latest reply: Apr 3, 2013 7:21 AM by 996721 RSS

Analysis of a trace - tkprof

996721 Newbie
Currently Being Moderated
Hello, I would like to locate the root of a very slow execution of a package at the base. For this to make a trace session on the last run it took 77 minutes to complete.

Then he saw the information on after turning it with tkprof. In the first part are the most expensive operations, and ultimately the overall results.

Database Version: 10.2.0.4.0

Standard Edition - RAC - ASM

total RAM        16G
sga_target      1504M
db_cache_size 0
owner            XAJTDB

--Package/procedure executed (from a job)
BEGIN HISR_FUTURE.p_hisr_future_all; END;
--file  xa212_j000_14811348.trc
TKPROF: Release 10.2.0.4.0 - Production on Fri Feb 1 15:23:26 2013

Copyright (c) 1982, 2007, Oracle.  All rights reserved.

Trace file: xa212_j000_14811348.trc
Sort options: fchela  

*SELECT MAX(UTCTIME)* 
*FROM*
 *CONECT_01 WHERE POINTNUMBER=:device_1*


call             count       cpu        elapsed       disk      query     current    rows
Parse         1776        0.05       0.03           0                0           0            0
Execute     1776        0.04       0.11           0               0            0            0
Fetch         3553       51.58     2256.05      405620  552615     0           1776

total       7105        51.67     2256.21      405620  552615     0           1776

Misses in library cache during parse: 0
Misses in library cache during execute: 1
Parsing user id: 57  (XAJTDB)   (recursive depth: 2)

Rows     Execution Plan
      0  SELECT STATEMENT   MODE: ALL_ROWS
      0   SORT (AGGREGATE)
      0    FIRST ROW
      0     INDEX   MODE: ANALYZED (FULL SCAN (MIN/MAX)) OF 
                'CONECT_01_PK' (INDEX (UNIQUE))


*SELECT MAX(UTCTIME)* 
*FROM*
 *STATUS_01 WHERE POINTNUMBER=:device_1*


call          count       cpu    elapsed       disk      query    current     rows
Parse       8206      0.20       0.15          0          0          0           0
Execute   8206      0.25       0.55          0          0          0           0
Fetch     16412     23.09      38.80       39     869129      0        8206

total      32824     23.54      39.50        39     869129      0        8206

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 57  (XAJTDB)   (recursive depth: 2)

Rows     Row Source Operation
      1  SORT AGGREGATE (cr=35 pr=33 pw=0 time=209038 us)
      1   FIRST ROW  (cr=35 pr=33 pw=0 time=209020 us)
      1    INDEX FULL SCAN (MIN/MAX) STATUS_01_PK (cr=35 pr=33 pw=0 time=209019 us)(object id 79195)


Rows     Execution Plan
      0  SELECT STATEMENT   MODE: ALL_ROWS
      1   SORT (AGGREGATE)
      1    FIRST ROW
      1     INDEX   MODE: ANALYZED (FULL SCAN (MIN/MAX)) OF 
                'STATUS_01_PK' (INDEX (UNIQUE))


*OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS*

call     count       cpu    elapsed       disk      query    current     rows
Parse        0      0.00       0.00          0          0          0           0
Execute    0      0.00       0.00          0          0          0           0
Fetch       0      0.00       0.00          0          0          0           0

total        0      0.00       0.00          0          0          0           0

Misses in library cache during parse: 0


*OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS*

call          count        cpu      elapsed           disk         query      current        rows
Parse       97568       4.17         4.94              0             38              2           0
Execute 111405    146.92    2382.98     465031    1337316    1715361       85314
Fetch      46033     75.20     2297.66     406057    1461528               0       36908

total      255006    226.29    4685.59     871088    2798882    1715363      122222

Misses in library cache during parse: 8451
Misses in library cache during execute: 153

94798  user  SQL statements in session.
 4557  internal SQL statements in session.
99355  SQL statements in session.
   48  statements EXPLAINed in this session.

Trace file: xa212_j000_14811348.trc
Trace file compatibility: 10.01.00
Sort options: fchela  
       1  session in tracefile.
   94798  user  SQL statements in trace file.
    4557  internal SQL statements in trace file.
   99355  SQL statements in trace file.
    8398  unique SQL statements in trace file.
      48  SQL statements EXPLAINed using schema:
           XAJTDB.prof$plan_table
             Default table was used.
             Table was created.
             Table was dropped.
  707680  lines in trace file.
    2502  elapsed seconds in trace file.
I think the memory settings are correct.

May bring me ideas on these overall results indicate?

The tables involved have a large volume of data (to 15 million, as appropriate). They are not partitioned (remember is Standard Edition) , is this one of the reasons why the job run so slow?.

Please require me more information if necessary.

Thanks!

Edited by: user12086565 on 26/03/2013 07:38

Edited by: user12086565 on 26/03/2013 09:31
  • 1. Re: Analysis of a trace - tkprof
    Mohamed Houri Pro
    Currently Being Moderated
    Could you please format your code using the code tag. And remember that there is a preview tab that allows you to previous your post before submitting it.

    For a starting point on how to interpret TKRPOF you can read the following blog article I wrote several months ago

    http://hourim.wordpress.com/2012/09/14/tuning-by-tkprof-a-case-study/

    Best regards
    Mohamed Houri
    www.hourim.wordpress.com
  • 2. Re: Analysis of a trace - tkprof
    996721 Newbie
    Currently Being Moderated
    Thanks, I'll start there then!. Anyway I would get from him, a preliminary look of the case, if possible.

    I used the tag to enclose the code, I do not understand because the format is not be correct.

    Thanks and regards!
  • 3. Re: Analysis of a trace - tkprof
    sb92075 Guru
    Currently Being Moderated
    user12086565 wrote:
    Thanks, I'll start there then!. Anyway I would get from him, a preliminary look of the case, if possible.

    I used the tag to enclose the code, I do not understand because the format is not be correct.
    used wrongly

    terminate with line below
  • 4. Re: Analysis of a trace - tkprof
    996721 Newbie
    Currently Being Moderated
    Mohamed Hello, I come from your forum, and after reading the article, I need to know:

    From the overall results:

    - I do not have the same number of physical reads (871,088) and buffer reads (2,798,882).

    - If there is a big difference between elapsed time (4685.59 s) and CPU time (226.29)


    - In total:
    - Execute 111405
    - Rows 122 222
    - 8245 Misses in library cache During parse
    I have not:
     SQL * Net message to client
      SQL * Net message from client
      db file scattered read
      db file sequential read
    rows / fetch = 122222/46033 = 2.65
    
    TABLE ACCESS FULL:
    
        RLS 224 TABLE ACCESS FULL $ (cr = 168 pr = 2 pw = 0 time = 14027 us)
        RLS 224 TABLE ACCESS FULL $ (cr = 168 pr = 0 pw = 0 time = 1637 us)
         38 TABLE ACCESS FULL HISRDEVICEDEFINITION (cr = 189 pr = 6 pw = 0 time = 22413 us)
          0 TABLE ACCESS FULL GDCTIE (cr = 3 pr = 1 pw = 0 time = 18613 us)
        360 TABLE ACCESS FULL HISRDEBUG_DAT (cr = 2520 pr = 0 pw = 0 time = 15164 us)
          0 TABLE ACCESS FULL AREA (cr = 7 pr = 5 pw = 0 time = 16151 us)
         39 TABLE ACCESS FULL HISRDEVICERANGE (cr = 210 pr = 0 pw = 0 time = 1675 us)
       1890 TABLE ACCESS FULL HISRDEVICEDEFINITION (cr = 210 pr = 0 pw = 0 time = 17048 us)
         27 TABLE ACCESS FULL HISRDEVICERANGE (cr = 168 pr = 0 pw = 0 time = 1740 us)
       1512 TABLE ACCESS FULL HISRDEVICEDEFINITION (cr = 168 pr = 0 pw = 0 time = 12108 us)
         27 TABLE ACCESS FULL HISRDEVICERANGE (cr = 168 pr = 6 pw = 0 time = 8647 us)
          0 TABLE ACCESS FULL DYNAMICSCHEDULE (cr = 3 pr = 1 pw = 0 time = 8621 us)
          1 TABLE ACCESS FULL DUAL (cr = 3 pr = 2 pw = 0 time = 5037 us)
       8206 TABLE ACCESS FULL TEMPDEVTABLE1 (cr = 16 pr = 0 pw = 0 time = 41 us)
          8 TABLE ACCESS FULL RLS $ (cr = 3 pr = 0 pw = 0 time = 64 us)
         12 TABLE ACCESS FULL HISRDEVICERANGE (cr = 42 pr = 0 pw = 0 time = 337 us)
        378 TABLE ACCESS FULL HISRDEVICEDEFINITION (cr = 42 pr = 0 pw = 0 time = 3317 us)
         27 TABLE ACCESS FULL HISRDEVICERANGE (cr = 215 pr = 0 pw = 0 time = 1643 us)
         27 TABLE ACCESS FULL HISRDEVICERANGE (cr = 168 pr = 0 pw = 0 time = 991 us)
          3 TABLE ACCESS FULL FIDEVICESETHELPER (cr = 21 pr = 6 pw = 0 time = 20396 us)
    Is the "time" in second units?

    Edited by: user12086565 on 26/03/2013 09:32
  • 5. Re: Analysis of a trace - tkprof
    Hemant K Chitale Oracle ACE
    Currently Being Moderated
    time = 14027 us
    the "us" is "microseconds".


    Hemant K Chitale
  • 6. Re: Analysis of a trace - tkprof
    Nikolay Savvinov Guru
    Currently Being Moderated
    Hi,

    as far as I could understand from your post your problem is that you have a statement that executes very quickly (a fraction of a second), but it is called so many times within your package that this adds up to a significant amount of time. There are two very similar statements in your tkprof output, one against CONECT_01, the other one against STATUS_01. The former is responsible for some 35 minutes of the execution time, while the latter for only ~39 seconds so it can be neglected.

    For some reason, the trace file doesn't contain the actual execution plan with rowsource stats for the query against CONECT_01 (maybe the cursor wasn't closed properly -- next time I recommend that you end tracing by exiting the session, not by ALTER SESSION SET EVENTS ... '... context off' or dbms_monitor). But from the explain plan the picture is more or less clear: the statement is doing an INDEX FAST FULL SCAN (MIN/MAX) and that's what's consuming resources (and time).

    That's a bit surprising because unlike regular INDEX FAST FULL SCAN, INDEX FAST FULL SCAN (MIN/MAX) is not supposed to traverse the entire index: rather, it should quickly navigate to the first block on either end of the index, and return the value. The fact that it's taking about 300 logical I/O operations (instead of something more like 2 or 3) is indicating that you're probably facing a bug. In the MOS database there is one that affects your version (10.2.0.4) and has similar symptoms:

    Bug 11834402 : CBO CHOOSES A SLOW INDEX FULL SCAN (MIN/MAX) OVER A MUCH FASTER INDEX RANGE SCAN

    maybe that's what is hitting you.

    Your options are:

    1) upgrade (does not guarantee that the problem goes away, because some varieties of this bug were noticed on 11.x versions; but you need to upgrade anyways since your version is no longer fully supported)
    2) raise an SR (probably won't do much good because you're version is no longer fully supported)
    3) find a workaround, e.g. something like:
    select *
    from
    (
       SELECT UTCTIME 
       FROM
       CONECT_01 WHERE POINTNUMBER=:device_1
       ORDER BY UTCTIME DESC
    )
    where rownum=1
    (if it doesn't work out of the box, try adding INDEX_DESC hint -- I vaguely recall having trouble getting a similar query to work without hints on 10.2.0.4)

    Best regards,
    Nikolay
  • 7. Re: Analysis of a trace - tkprof
    Mohamed Houri Pro
    Currently Being Moderated
    Hi Carlos,
    *SELECT MAX(UTCTIME)* 
    *FROM*
     *CONECT_01 WHERE POINTNUMBER=:device_1*
     
     
    call         count       cpu       elapsed       disk      query     current    rows
    Parse        1776       0.05       0.03           0        0           0         0
    Execute      1776       0.04       0.11           0        0           0         0
    Fetch        3553       51.58      2256.05      405620    552615       0         1776 
    total        7105       51.67      2256.21      405620    552615       0         1776
    Let me just try to interpret the above part of your trace file.
    The first fundamental remark I can point out is that you are doing a parse for each execution. Ideally you have to parse 1 and execute many. Here the ratio Parse/Execute = 1 which means then you parsed this query each and every time you executed it and that needs to be corrected. You are performing many soft parses which can alter the total query response time.

    The second remark is that you did 1776 executions to generate 1776 rows (1 row for each execution of the above query). But why are you doing 405620/1776 = 228 physical read and 552615/1776 = 311 logical reads to generate 1 row ? Are you enforcing your primary key with a non UNIQUE INDEX? Is your index connect_01_pk non unique?
    Is the "time" in second units?
    (cr = 168 pr = 2 pw = 0 time = 14027 us)
    As Hermant has already pointed, us = micro seconds.

    Update
    'CONECT_01_PK' (INDEX (UNIQUE))
    Sorry, I have not looked carrefully to see that the index CONECT_01_PK is UNIQUE

    Best regards
    Mohamed Houri
    www.hourim.wordpress.com

    Edited by: Mohamed Houri on 27 mars 2013 02:05
  • 8. Re: Analysis of a trace - tkprof
    Jonathan Lewis Oracle ACE Director
    Currently Being Moderated
    user12086565 wrote:
    *SELECT MAX(UTCTIME)* 
    *FROM*
    *CONECT_01 WHERE POINTNUMBER=:device_1*
    
    
    call             count       cpu        elapsed       disk      query     current    rows
    Parse         1776        0.05       0.03           0                0           0            0
    Execute     1776        0.04       0.11           0               0            0            0
    Fetch         3553       51.58     2256.05      405620  552615     0           1776
    
    total       7105        51.67     2256.21      405620  552615     0           1776
    
    Misses in library cache during parse: 0
    Misses in library cache during execute: 1
    Parsing user id: 57  (XAJTDB)   (recursive depth: 2)
    
    Rows     Execution Plan
    0  SELECT STATEMENT   MODE: ALL_ROWS
    0   SORT (AGGREGATE)
    0    FIRST ROW
    0     INDEX   MODE: ANALYZED (FULL SCAN (MIN/MAX)) OF 
    'CONECT_01_PK' (INDEX (UNIQUE))
    
    
    *SELECT MAX(UTCTIME)* 
    *FROM*
    *STATUS_01 WHERE POINTNUMBER=:device_1*
    
    
    call          count       cpu    elapsed       disk      query    current     rows
    Parse       8206      0.20       0.15          0          0          0           0
    Execute   8206      0.25       0.55          0          0          0           0
    Fetch     16412     23.09      38.80       39     869129      0        8206
    
    total      32824     23.54      39.50        39     869129      0        8206
    
    Misses in library cache during parse: 1
    Misses in library cache during execute: 1
    Optimizer mode: ALL_ROWS
    Parsing user id: 57  (XAJTDB)   (recursive depth: 2)
    
    Rows     Row Source Operation
    1  SORT AGGREGATE (cr=35 pr=33 pw=0 time=209038 us)
    1   FIRST ROW  (cr=35 pr=33 pw=0 time=209020 us)
    1    INDEX FULL SCAN (MIN/MAX) STATUS_01_PK (cr=35 pr=33 pw=0 time=209019 us)(object id 79195)
    Can we see the index definitions for the two indexes, and the column definitions for all the columns involved.
    Could we also see the execution plans pulled from memory at run-time (dbms_xplan.display_cursor()) so that we can see what Oracle is doing with the predicates.
    Can we also see some statistics: table.num_rows, index.num_rows, index.leaf_blocks, column.num_distinct and last_analyzed for all objects.


    One interpretation of the results is that, as Nikolay pointed out, you've found a bug in the optimizer - or possibly you've fooled the optimizer because the statistics are not representative of the data - another interpretation is that the combination of the nature and use of the index (which looks like a time-based index) has left you with a massively inefficient index which the optimizer can't see as such.

    Regards
    Jonathan Lewis
  • 9. Re: Analysis of a trace - tkprof
    996721 Newbie
    Currently Being Moderated
    Thanks!

    I had doubts about this, but now were cleared.

    Regards!
  • 10. Re: Analysis of a trace - tkprof
    Randolf Geist Oracle ACE Director
    Currently Being Moderated
    user12086565 wrote:
    Then he saw the information on after turning it with tkprof. In the first part are the most expensive operations, and ultimately the overall results.
    According to your overall results you've spent approx. the same amount of time in the Execute phase as in the Fetch phase - so your most expensive operations posted miss these "most expensive executions".

    It might be worth to look at those as well.

    Randolf
  • 11. Re: Analysis of a trace - tkprof
    Randolf Geist Oracle ACE Director
    Currently Being Moderated
    Nikolay Savvinov wrote:
    That's a bit surprising because unlike regular INDEX FAST FULL SCAN, INDEX FAST FULL SCAN (MIN/MAX) is not supposed to traverse the entire index: rather, it should quickly navigate to the first block on either end of the index, and return the value. The fact that it's taking about 300 logical I/O operations (instead of something more like 2 or 3) is indicating that you're probably facing a bug. In the MOS database there is one that affects your version (10.2.0.4) and has similar symptoms:
    Hi Nikolay,

    since it hasn't been mentioned yet I just wanted to remind of the possible side-effects of read consistency. Theoretically it is possible to see such high logical I/Os without hitting a bug if a lot of undo needs to be applied, but of course it could also be a bad decision of the optimizer / index in bad state as mentioned by you and Jonathan.

    Randolf
  • 12. Re: Analysis of a trace - tkprof
    996721 Newbie
    Currently Being Moderated
    Hello, I will try to attach the information that I requested.

    Thank you!
  • 13. Re: Analysis of a trace - tkprof
    996721 Newbie
    Currently Being Moderated
    Hi, here the output of the information request:
    PROMPT ALTER TABLE xajtdb.status_01 ADD CONSTRAINT status_01_pk PRIMARY KEY
    ALTER TABLE xajtdb.status_01
      ADD CONSTRAINT status_01_pk PRIMARY KEY (
        utctime,
        pointnumber
      )
      USING INDEX
        TABLESPACE xa_hisr_hist_data_ts
        PCTFREE   10
        INITRANS   2
        MAXTRANS 255
        STORAGE (
          INITIAL 1310720 K
          NEXT          0 K
          MINEXTENTS    1
          MAXEXTENTS    UNLIMITED
          PCTINCREASE   0
          FREELISTS     1
          FREELIST GROUPS 1
          BUFFER_POOL DEFAULT
        )
        LOGGING
        NOCOMPRESS
    /
    
    PROMPT ALTER TABLE xajtdb.conect_01 ADD CONSTRAINT conect_01_pk PRIMARY KEY
    ALTER TABLE xajtdb.conect_01
      ADD CONSTRAINT conect_01_pk PRIMARY KEY (
        utctime,
        pointnumber
      )
      USING INDEX
        TABLESPACE xa_hisr_hist_data_ts
        PCTFREE   10
        INITRANS   2
        MAXTRANS 255
        STORAGE (
          INITIAL  647168 K
          NEXT          0 K
          MINEXTENTS    1
          MAXEXTENTS    UNLIMITED
          PCTINCREASE   0
          FREELISTS     1
          FREELIST GROUPS 1
          BUFFER_POOL DEFAULT
        )
        LOGGING
        NOCOMPRESS
    /
    
    select
    table_name,num_rows,
    blocks,avg_space,
    chain_cnt,avg_row_len,
    sample_Size
    from dba_tables
    where table_name = 'CONECT_01';
    
    TABLE_NAME NUM_ROWS BLOCKS AVG_SPACE CHAIN_CNT AVG_ROW_LEN SAMPLE_SIZE
    CONECT_01  16195993  92861      1738         0          24        5484
    
    ===============================================================================
    
    select
    table_name,num_rows,
    blocks,avg_space,
    chain_cnt,avg_row_len,
    sample_Size
    from dba_tables
    where table_name = 'STATUS_01';
    
    TABLE_NAME NUM_ROWS BLOCKS AVG_SPACE CHAIN_CNT AVG_ROW_LEN SAMPLE_SIZE
    STATUS_01  46835851 262443       948         0          23        5563
    
    ===============================================================================
    
    select
    index_name,num_rows,
    leaf_blocks,sample_Size
    from dba_indexes
    where table_name = 'CONECT_01';
    
    INDEX_NAME        NUM_ROWS LEAF_BLOCKS SAMPLE_SIZE
    CONECT_01_PK      15883091       84054      199734
    CONECT_01_I_POINT 16110657       85489      217286
    
    ===============================================================================
    
    select
    index_name,num_rows,
    leaf_blocks,sample_Size
    from dba_indexes
    where table_name = 'STATUS_01';
    
    INDEX_NAME        NUM_ROWS LEAF_BLOCKS SAMPLE_SIZE
    I_STATUS_01_POINT 45950607      235104      210693
    STATUS_01_PK      46651458      242459      204916
    
    ===============================================================================
    
    select OWNER,TABLE_NAME,NUM_DISTINCT,LAST_ANALYZED
    from ALL_TAB_COLUMNS
    where TABLE_NAME = 'CONECT_01’;
    
    OWNER  TABLE_NAME NUM_DISTINCT LAST_ANALYZED
    XAJTDB CONECT_01          5646 01/04/2013 22:19:12
    XAJTDB CONECT_01          2777 01/04/2013 22:19:12
    XAJTDB CONECT_01           695 01/04/2013 22:19:12
    XAJTDB CONECT_01             5 01/04/2013 22:19:12
    
    ===============================================================================
    
    select OWNER,TABLE_NAME,NUM_DISTINCT,LAST_ANALYZED
    from ALL_TAB_COLUMNS
    where TABLE_NAME = 'STATUS_01';
    
    OWNER  TABLE_NAME NUM_DISTINCT LAST_ANALYZED
    XAJTDB STATUS_01          5626 01/04/2013 22:21:17
    XAJTDB STATUS_01          8342 01/04/2013 22:21:17
    XAJTDB STATUS_01            27 01/04/2013 22:21:17
    XAJTDB STATUS_01             2 01/04/2013 22:21:17
    
    ===============================================================================
    Thanks!

Legend

  • Correct Answers - 10 points
  • Helpful Answers - 5 points