13 Replies Latest reply: Apr 3, 2013 9:21 AM by 996721 RSS

    Analysis of a trace - tkprof

    996721
      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
          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
            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
              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
                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
                  time = 14027 us
                  the "us" is "microseconds".


                  Hemant K Chitale
                  • 6. Re: Analysis of a trace - tkprof
                    Nikolay Savvinov
                    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
                      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
                        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
                          Thanks!

                          I had doubts about this, but now were cleared.

                          Regards!
                          • 10. Re: Analysis of a trace - tkprof
                            Randolf Geist
                            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
                              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
                                Hello, I will try to attach the information that I requested.

                                Thank you!
                                • 13. Re: Analysis of a trace - tkprof
                                  996721
                                  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!