This discussion is archived
1 2 3 4 Previous Next 46 Replies Latest reply: Mar 23, 2010 5:39 PM by 733022 Go to original post RSS
  • 15. Re: Tuning a sql using tkprof
    CharlesHooper Expert
    Currently Being Moderated
    user600979 wrote:
    I've an error:


    Error: format 'ALLSTATS LAST' not valid for DBMS_XPAN.DISPLAY_CURSOR()
    ALLSTATS LAST is a valid format parameter (at least on 10.2.0.1 and above), you can see a sample output with that format parameter here:
    http://hoopercharles.wordpress.com/2010/03/01/dbms_xplan-format-parameters/

    I suspect that you are encountering a permission problem - permissions must be granted on 3 views to the user that is executing the DBMS_XPAN call. See my last response in this thread for the list of views.

    If you are still having trouble with DBMS_XPAN, make certain that the STATISTICS_LEVEL is set to 'TYPICAL' and create the trace file/TKPROF for the version of the SQL statement with the FULL hint, and post that output instead.

    Charles Hooper
    Co-author of "Expert Oracle Practices: Oracle Database Administration from the Oak Table"
    http://hoopercharles.wordpress.com/
    IT Manager/Oracle DBA
    K&M Machine-Fabricating, Inc.
  • 16. Re: Tuning a sql using tkprof
    AleC Newbie
    Currently Being Moderated
    I've done what you suggested:

    SELECT  /*+ FULL(m) */
          COUNT ( * )    
      FROM            I_JOURNAL m
                   INNER JOIN
                      LIU_TYPES lt
                   ON (m.LIU_TYPE = lt.LIU_TYPE)
                INNER JOIN
                   LAWFUL_I             li
                ON (m.LIID = li.LIID)
             LEFT OUTER JOIN
                PHONE_BOOK pb
    ...
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.01       0.00          0          0          0           0
    Execute      1      0.08       0.07          0          0          0           0
    Fetch        2    130.42     127.68     198250     262968          0           1
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        4    130.51     127.76     198250     262968          0           1
    
    Misses in library cache during parse: 1
    Misses in library cache during execute: 1
    Optimizer mode: ALL_ROWS
    Parsing user id: 50
    
    Rows     Row Source Operation
    -------  ---------------------------------------------------
          1  SORT AGGREGATE (cr=262968 pr=198250 pw=0 time=127688606 us)
     891490   HASH JOIN RIGHT OUTER (cr=262968 pr=198250 pw=0 time=125301874 us)
      28489    INDEX RANGE SCAN OBJ#(45035) (cr=130 pr=0 pw=0 time=142591 us)(object id 45035)
     891490    HASH JOIN  (cr=262838 pr=198250 pw=0 time=109671105 us)
         15     TABLE ACCESS FULL OBJ#(44893) (cr=7 pr=0 pw=0 time=320 us)
     891577     HASH JOIN  (cr=262831 pr=198250 pw=0 time=95413547 us)
         61      INLIST ITERATOR  (cr=185 pr=0 pw=0 time=6619 us)
         61       TABLE ACCESS BY INDEX ROWID OBJ#(44860) (cr=185 pr=0 pw=0 time=5734 us)
         61        INDEX RANGE SCAN OBJ#(45023) (cr=122 pr=0 pw=0 time=1831 us)(object id 45023)
    5010465      TABLE ACCESS FULL OBJ#(47625) (cr=262646 pr=198250 pw=0 time=35075329 us)
    
    
    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      SQL*Net message to client                       2        0.00          0.00
      db file scattered read                      23383        0.00          3.28
      db file sequential read                      8155        0.00          0.23
      SQL*Net message from client                     2        0.00          0.00
    ********************************************************************************
    
    alter session set events '10046 trace name context forever,level 8'
  • 17. Re: Tuning a sql using tkprof
    CharlesHooper Expert
    Currently Being Moderated
    Thank you for providing the requested information. Unless I have missed something, I do not see the reason for the high CPU consumption in the 10046 trace summary that was generated by TKPROF.

    The time for disk I/O completion is almost non-existent when you consider the number of I/Os that are performed (the average I/O time is very fast). The 'db file scattered read' wait event indicates that the DB_FILE_MULTIBLOCK_READ_COUNT parameter is probably set to a value between 9 and 16: (198250 - 8155) / 23383 = 8.13 blocks per multi-block read, but that low value does not appear to be causing an issue. The full table scan of I_JOURNAL did complete faster than the index lookup of that table, but it appears that the overall execution time increased above what it was before.

    You did not mention the exact release of Oracle that you were using, but I assume that it is 10.1.0.x based on the problem that you had with the format parameters of DBMS_XPLAN. I suggest the following:
    * Review all of the initialization parameters that appear in V$SQL_OPTIMIZER_ENV for this SQL statement's SQL_ID. This will not necessarily explain why the CPU consumption is so high in comparision with the disk access time, but it might help. You might also review all of the other parameters that are set.
    * Determine if the physical memory in the server has been exceeded - you should be able to use operating system tools to do this, but be careful about double-counting the shared memory segments. If large memory page support is an option, make certain that it is enabled. The server might be consuming a lot of memory for a file cache, which then might limit the physical memory available for Oracle, and cause an excessive use of the operating system page file and long CPU waits while "in-memory" logical I/Os are actually fetched from the page file.
    * Consider performing stack traces on the Oracle process that is used by this session to see where the CPU time is being consumed. See Tanel Poder's blog for methods of performing the stack traces: http://blog.tanelpoder.com/
    * Investigate whether there is a lot of competion for CPU time on the server - this might not be a problem, but could be an issue if the OS scheduler repeatedly switches the process off the CPU (it would seem that when this happens there would just be unexplained gaps in the CPU time).
    * Verify that the STATISTICS_LEVEL parameter is NOT set to ALL.

    Someone else might see something that I missed in the trace file outputs that you provided.

    Charles Hooper
    Co-author of "Expert Oracle Practices: Oracle Database Administration from the Oak Table"
    http://hoopercharles.wordpress.com/
    IT Manager/Oracle DBA
    K&M Machine-Fabricating, Inc.
  • 18. Re: Tuning a sql using tkprof
    AleC Newbie
    Currently Being Moderated
    Thank you for the hints, I'm going to work on them.

    The other problem is the wrong row count extimation, the explain plan is:
    select PLAN_TABLE_OUTPUT     from table(dbms_xplan.display_cursor(null,null,'RUNSTATS_LAST'));
    
    PLAN_TABLE_OUTPUT                                                                                                                                                                                       
    --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
                                                                                                                                                                                                            
    Plan hash value: 4183643102                                                                                                                                                                             
                                                                                                                                                                                                            
    -----------------------------------------------------------------------------------------------------------------------------                                                                           
    | Id  | Operation                        | Name                  | E-Rows | A-Rows | Buffers | Reads  | Writes | A-Time     |                                                                           
    -----------------------------------------------------------------------------------------------------------------------------                                                                           
    |   1 | SORT AGGREGATE                   |                       |      1 |      1 |     657K|    245K|      0 |00:01:40.79 |                                                                           
    |*  2 |  HASH JOIN RIGHT OUTER           |                       |  30607 |    894K|     657K|    245K|      0 |00:01:37.94 |                                                                           
    |*  3 |   INDEX RANGE SCAN               | PBK_GET_NORM_CIN_UK   |  25437 |  28490 |     130 |     19 |      0 |00:00:00.14 |                                                                           
    |*  4 |   HASH JOIN                      |                       |  30607 |    894K|     657K|    245K|      0 |00:01:23.16 |                                                                           
    |*  5 |    TABLE ACCESS FULL             | LIU_TYPES             |     16 |     15 |       7 |      0 |      0 |00:00:00.01 |                                                                           
    
    PLAN_TABLE_OUTPUT                                                                                                                                                                                       
    --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
    |*  6 |    TABLE ACCESS BY INDEX ROWID   | I_JOURNAL         |   1221 |    894K|     657K|    245K|      0 |00:01:01.70 |                                                                           
    |   7 |     NESTED LOOPS                 |                       |  31449 |    894K|    5428 |   5099 |      0 |00:00:24.02 |                                                                           
    |   8 |      INLIST ITERATOR             |                       |        |     61 |     206 |      1 |      0 |00:00:00.01 |                                                                           
    |*  9 |       TABLE ACCESS BY INDEX ROWID| LAWFUL_I       |     26 |     61 |     206 |      1 |      0 |00:00:00.01 |                                                                           
    |* 10 |        INDEX RANGE SCAN          | LIN_ID_UK             |     61 |     61 |     122 |      0 |      0 |00:00:00.01 |                                                                           
    |* 11 |      INDEX RANGE SCAN            | IJL_LIN_FK_IX         |   5318 |    894K|    5222 |   5098 |      0 |00:00:09.99 |                                                                           
    ----------------------------------------------------------------------------------------------------------------------------- 
    What do you think about it?
  • 19. Re: Tuning a sql using tkprof
    CharlesHooper Expert
    Currently Being Moderated
    user600979 wrote:
    Thank you for the hints, I'm going to work on them.

    The other problem is the wrong row count extimation

    What do you think about it?
    The inaccurate cardinality estimates could be part of the problem. You have the CURSOR_SHARING parameter set to either FORCE or SIMILAR, and that could be impacting the cardinality estimates for later executions with different literal values (that are replaced with the :"SYS_B_nn bind variables) specified in the SQL statement when it is re-executed. It could also be that you are encountering a cardinality calculation error with the ANSI style join syntax, or that you have certain values in the SQL statement that are much more popular than other values, or you have correlated columns (value *x* in column A can only exist when value *y* is present in column B). If you have verified that statistics were collected recently for the tables and indexes, review the histograms that are present on the tables. Adding or removing a histogram on a table's column might yield better cardinality estimates for this SQL statement, while potentially causing problems for other SQL statements.

    One way to correct the cardinality estimates is through the use of hints, but I hestitated to suggest this because as the data volumes in the tables change, the hints become misleading/inaccurate - the same is probably also true when the literal values specified in the SQL statement change. For example, you could try something like this:
    {code}
    SELECT /*+ OPT_ESTIMATE(TABLE, M, ROWS=894000) OPT_ESTIMATE(TABLE, LI, ROWS=61) */
    COUNT ( * )
    FROM I_JOURNAL m
    INNER JOIN
    LIU_TYPES lt
    ON (m.LIU_TYPE = lt.LIU_TYPE)
    INNER JOIN
    LAWFUL_I li
    ON (m.LIID = li.LIID)
    LEFT OUTER JOIN
    PHONE_BOOK pb
    ...
    {code}
    (CARDINALITY hints might be used in place of the OPT_ESTIMATE hints.)

    If you want to try a non-ANSI style SQL statement, it might look something like this (I suggest first trying without the OPT_ESTIMATE hints):
    {code}
    SELECT /*+ OPT_ESTIMATE(TABLE, M, ROWS=894000) OPT_ESTIMATE(TABLE, LI, ROWS=61) */
    COUNT ( * )
    FROM
    I_JOURNAL m,
    LIU_TYPES lt,
    LAWFUL_I li,
    PHONE_BOOK pb
    WHERE
    m.LIU_TYPE = lt.LIU_TYPE
    AND m.LIID = li.LIID
    AND m.NORM_CIN = pb.NORM_CIN(+)
    AND pb.DELETION_DATE IS NULL
    AND pb.OPERATOR_ID(+) = :"SYS_B_00"
    AND LIU_PRIORITY >= :"SYS_B_01"
    AND (li.ID IN
    ...
    {code}
    (In the above replace the :"SYS_B_nn" bind variables with the literals that are normally present in the SQL statement.)

    Charles Hooper
    Co-author of "Expert Oracle Practices: Oracle Database Administration from the Oak Table"
    http://hoopercharles.wordpress.com/
    IT Manager/Oracle DBA
    K&M Machine-Fabricating, Inc.
  • 20. Re: Tuning a sql using tkprof
    AleC Newbie
    Currently Being Moderated
    I've tried to use your suggestions:

    - alter session set cursor_sharing = 'EXACT'
    - HINTS
    - query "No ANSI" JOIN

    but the explain plan and the execution time are not changed.
  • 21. Re: Tuning a sql using tkprof
    CharlesHooper Expert
    Currently Being Moderated
    user600979 wrote:
    I've tried to use your suggestions:

    - alter session set cursor_sharing = 'EXACT'
    - HINTS
    - query "No ANSI" JOIN

    but the explain plan and the execution time are not changed.
    Those suggestions were offered to correct the cardinality estimates problem that you mentioned in your previous post. If you force a hard parse and check the execution plan with DBMS_XPLAN the cardinality estimates will have hopefully become more accurate. The more accurate cardinality estimates might have triggered a change in the execution plan, but that change was not significant.

    As I have mentioned in a couple of my previous posts, something is causing the session to consume a significant amount of CPU time when compared to the time required for physical I/Os - considering that the number of logical I/Os is only slightly higher than the number of physical I/Os, the CPU time should be very little (maybe 1 second?).

    I am interested in knowing what is triggering that excessive CPU time. Please investigate what I mentioned previously and post what you find.

    Charles Hooper
    Co-author of "Expert Oracle Practices: Oracle Database Administration from the Oak Table"
    http://hoopercharles.wordpress.com/
    IT Manager/Oracle DBA
    K&M Machine-Fabricating, Inc.
  • 22. Re: Tuning a sql using tkprof
    AleC Newbie
    Currently Being Moderated
    You wrote

    See Tanel Poder's blog for methods of performing the stack traces

    but I cannot find the right discussion in that Blog. Could you help me?
  • 23. Re: Tuning a sql using tkprof
    CharlesHooper Expert
    Currently Being Moderated
    user600979 wrote:
    You wrote

    See Tanel Poder's blog for methods of performing the stack traces

    but I cannot find the right discussion in that Blog. Could you help me?
    There are several posts that should help, below are a couple of those posts:
    http://blog.tanelpoder.com/2009/04/24/tracing-oracle-sql-plan-execution-with-dtrace/
    http://blog.tanelpoder.com/2010/01/15/beyond-oracle-wait-interface-part-2/
    http://blog.tanelpoder.com/2008/10/31/advanced-oracle-troubleshooting-guide-part-9-process-stack-profiling-from-sqlplus-using-ostackprof/

    Related:
    http://blog.tanelpoder.com/2007/09/06/advanced-oracle-troubleshooting-guide-part-3-more-adventures-in-process-stack/

    Charles Hooper
    Co-author of "Expert Oracle Practices: Oracle Database Administration from the Oak Table"
    http://hoopercharles.wordpress.com/
    IT Manager/Oracle DBA
    K&M Machine-Fabricating, Inc.
  • 24. Re: Tuning a sql using tkprof
    jgarry Guru
    Currently Being Moderated
    Just an odd thought out of left field:

    On the original query, instead of

    ... select count(*) ...

    try:

    ...select count(*),max(m.display_date)...

    I'm just wondering if the aggregate of a non-key column might poke at the optimizer to try something different than what it is doing or a full scan of the journal table, though probably that will just force the full scan.

    I'm guessing there is some housekeeping of that ijl..fk_ix key that is just making the cpu go nuts reading things too much. Can we get a clue what the columns are in that key versus what the primary key on the table is? Maybe you just need a different index.
  • 25. Re: Tuning a sql using tkprof
    jgarry Guru
    Currently Being Moderated
    Another thought: What non-standard init.ora parameters are you using? In particular, any that affect the optimizer? Try turning them off for the session.
  • 26. Re: Tuning a sql using tkprof
    Lakmal Rajapakse Expert
    Currently Being Moderated
    Just curious - if an operator has 800000 activities do you display all of it or just a small subset of it?
  • 27. Re: Tuning a sql using tkprof
    AleC Newbie
    Currently Being Moderated
    We display the first 100 records.
    The count is used to know the number of the pages.
  • 28. Re: Tuning a sql using tkprof
    AleC Newbie
    Currently Being Moderated
    I've tried

    ...select count(*),max(m.display_date)...

    but the explain plan is not changed.

    I've tried to change the init parameters
    cursor_sharing='EXACT' (it was 'SIMILAR')
    db_file_multiblock_read_count=32 (it was 16)

    but the explain plan is not changed.
  • 29. Re: Tuning a sql using tkprof
    Lakmal Rajapakse Expert
    Currently Being Moderated
    I thought that might be the case that is why I asked the question. What you are doing is just wrong. To get the count you have fetch all the rows - and then you go and display the first 100 rows - this is just a waste of time. Do you think when you do a Google search it gives you the actual number of rows that match your search criteria - no it does not - it gives you an estimate of the rows it expects to find. You need to change your design to remove the count.

Legend

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