Oracle Scratchpad

November 9, 2006

dbms_xplan in 10g

Filed under: dbms_xplan,Execution plans,Hints,Tuning — Jonathan Lewis @ 9:17 pm GMT Nov 9,2006

[More on dbms_xplan.display_cursor()]

If you’re using 9i and haven’t learned about the dbms_xplan package, then you should take a good look at it right away. It’s (usually) a much better way of getting execution plans from your system than writing your own queries against the plan_table.

If you’ve been using dbms_xplan, and upgraded from 9i to 10g, make sure that you look at the new features – there are some things which are really useful, and this note is about just one of them.

dbms_xplan.display_cursor()


In 10g, Oracle introduced a new function in the package dbms_xplan that can read the in-memory execution plan (v$sql_plan and associated structures).  The call is the display_cursor() call, and takes three optional parameters, the sql_id and child_number of the SQL statement you want to see the plan for, and a formatting string.

The best bit of this function shows up when you look at the script that generates it($ORACLE_HOME/rdbms/admin/dbmsxpln.sql) when you decide to find out how to use the format parameter.  Here’s a “live” demo:

set serveroutput off        

select
	/*+
		gather_plan_statistics
		ordered use_nl(t1) index(t1)
	*/
	count(t1.n2), count(t2.n2)
from
	t2, t1
where
	t2.n2 = 45
and	t1.n1 = t2.n1
;        

COUNT(T1.N2) COUNT(T2.N2)
------------ ------------
         225          225        

select * from table(dbms_xplan.display_cursor(null,null,'ALLSTATS LAST'));        

PLAN_TABLE_OUTPUT
-------------------------------------
SQL_ID  98cw5a9c0pw33, child number 0
-------------------------------------
select  /*+   gather_plan_statistics   ordered use_nl(t1) index(t1)  */  count(t1.n2),
count(t2.n2) from  t2, t1 where  t2.n2 = 45 and t1.n1 = t2.n1        

Plan hash value: 3795562434        

-----------------------------------------------------------------------------------------------
| Id  | Operation                    | Name | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-----------------------------------------------------------------------------------------------
|   1 |  SORT AGGREGATE              |      |      1 |      1 |      1 |00:00:00.01 |     146 |
|   2 |   TABLE ACCESS BY INDEX ROWID| T1   |      1 |     15 |    225 |00:00:00.01 |     146 |
|   3 |    NESTED LOOPS              |      |      1 |    225 |    241 |00:00:00.02 |     116 |
|*  4 |     TABLE ACCESS FULL        | T2   |      1 |     15 |     15 |00:00:00.01 |      99 |
|*  5 |     INDEX RANGE SCAN         | T_I1 |     15 |     15 |    225 |00:00:00.01 |      17 |
-----------------------------------------------------------------------------------------------        

Predicate Information (identified by operation id):
---------------------------------------------------
   4 - filter("T2"."N2"=45)
   5 - access("T1"."N1"="T2"."N1")        

If you want to call this function, you need access to several of the dynamic performance views: v$session, v$sql, v$sql_plan and v$sql_plan_statistics_all seem to cover all the options between them; and v$sql_plan_statistics_all is the most useful one.

As you can see in the query above, I’ve not supplied an sql_id or child_number, and I’ve used the format ‘ALLSTATS LAST’. By default display_cursor() reports the last statement I executed and the effect of ‘ALLSTATS LAST’ is to report the actual execution stats alongside the predicted row counts.  [Update: note that this is the stats for the last execution, if you omit “last” then you get the sum of stats for all the executions that took place while rowsource execution stats were enabled. I have seen a couple of notes suggesting that you need to use “allstats all” to do this (I may have written one myself) but the “all” option isn’t necessary and adds lots of other bits of information.]

If you’ve ever got into Wolfgang Breitling’s “Tuning by Cardinality Feedback” – you’ve now got a tool that can make it a lot easier.

Footnotes

  • You’ll see that I set serveroutput off. If serveroutput is on when you call this function, the “last statement you ran” will be the (hidden) call to dbms_output that SQL*Plus runs after the execution of any other statement – so you won’t get the plan and statistics, you’ll see a note to the effect that Oracle “cannot fetch plan for SQL_ID: b3s1x9zqrvzvc, CHILD_NUMBER: 0”.
  • The hint /*+ gather_plan_statistics */ enables collection of rowsource execution statistics for the statement. It’s a “nearly undocumented” hint, in that the documentation seems to exist only in odd places like the script that generates the package and as part of the output of the function call if the statistics weren’t enabled when you try to report statistics.
  • You have to be a little careful comparing the actual and estimated row counts. They are not supposed to be the same in all cases. The estimated values are estimates for each execution of a rowsource, the actual values are the cumulative counts. So, for example, it is perfectly reasonable in line 5 to see E-rows = 15 and A-rows = 225, because line 5 Starts 15 times: so 225 actual rows = 15 starts * 15 estimated rows per start.

 

[More on dbms_xplan.display_cursor()]

31 Comments

  1. Jonathan,

    I’ve been using dbms_xplan.display for a while now, but could never seem to get dbms_xplan.display_cursor to work, I can’t thank you enough for pointing out the ‘gather_plan_statistics’ hint, which was the key to getting it to work.

    Keep up the blogging please!

    Comment by John Scott — November 9, 2006 @ 11:50 pm GMT Nov 9,2006

  2. I have been using 10g for a while but didn’t know about this. Thank you!!!

    Comment by Kirtan Desai — November 10, 2006 @ 4:25 am GMT Nov 10,2006

  3. well i knew about dbms_xplan but didn’t know about display_cursor.

    Comment by Kirtan Desai — November 10, 2006 @ 4:26 am GMT Nov 10,2006

  4. John, There are alternatives to the hint. Setting statistics_level = all, or _rowsource_execution_statistics = true, will enable the collection (and on some versions, just sql_trace = true does so as well). But the hint is the neatest.

    Comment by Jonathan Lewis — November 10, 2006 @ 7:21 am GMT Nov 10,2006

  5. This works particularly nicely in tools such as PL/SQL Developer where you can add your own tabs to the Session Browser window, and so you can define one named “Current Plan”, with the query as:

    SELECT plan_table_output
    FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR( :sql_id, :sql_child_number))

    Now you can easily see the execution plan for any active session.

    Comment by William Robertson — November 10, 2006 @ 4:37 pm GMT Nov 10,2006

  6. In Oracle 10g, dbms_xplan.display_awr can be used to get the historical information with respect to execution plans.

    Jaffar

    Comment by Jaffar Hussain — November 11, 2006 @ 7:19 am GMT Nov 11,2006

  7. […] A comment on my previous posting about dbms_xplan pointed out that in 10g you also get the function dbms_xplan.display_awr that allows you to report historical execution plans from the AWR (automatic workload repository). […]

    Pingback by dbms_xplan pt.2 « Oracle Scratchpad — November 15, 2006 @ 8:23 am GMT Nov 15,2006

  8. I found that 10gR1 (at least on AIX) does not have the ALLSTATS LAST parameter, but includes RUNSTATS_LAST and RUNSTATS_TOT instead of ALLSTATS. The script documentation for 10gR2 says that these are included for backwards compatibility and are replaced by IOSTATS.

    Comment by Daniel Fink — December 13, 2006 @ 11:20 pm GMT Dec 13,2006

  9. […] Plans in Memory Filed under: Infrastructure, Performance, Execution plans — Jonathan Lewis @ 8:42 pm UTC Dec 12,2006 In an earlier article I described how dbms_xplan.display_cursor() could be used to query memory to find the execution plans (and row source statistics) of recently executed SQL. […]

    Pingback by Plans in Memory « Oracle Scratchpad — December 30, 2006 @ 8:26 pm GMT Dec 30,2006

  10. […] — Jonathan Lewis @ 12:03 pm UTC Dec 22,2006 I’ve discussed the capabilities of the dbms_xplan package in a couple of posts already; and shown how useful it can be in two examples: understanding a […]

    Pingback by dbms_xplan - again « Oracle Scratchpad — February 1, 2007 @ 1:07 pm GMT Feb 1,2007

  11. […] blogged before about the improved features in 10g of the dbms_xplan package, in particular the display_cursor() procedure, with its option for displaying rowsource execution […]

    Pingback by Heisenberg « Oracle Scratchpad — April 26, 2007 @ 9:15 pm BST Apr 26,2007

  12. […] Since this was a 10g machine, I hunted down the query (v$sql.sql_text like …) and called the  dbms_xplan.display_cursor() procedure to show me the full plan. It looked a bit like […]

    Pingback by NLS « Oracle Scratchpad — July 26, 2007 @ 9:51 pm BST Jul 26,2007

  13. […] dbms_xplan in 10g « Oracle Scratchpad Oracle Scratchpad November 9, 2006 dbms_xplan in 10g Filed under: Execution plans, Tuning, Hints — Jonathan Lewis @ 9:17 pm UTC Nov 9,2006 If you’re using 9i and haven’t learned about the dbms_xplan package, then you should take a good l […]

    Pingback by 10g Application Oracle Server — September 13, 2007 @ 3:34 pm BST Sep 13,2007

  14. […] dbms_xplan(3) Filed under: Execution plans — Jonathan Lewis @ 8:01 am UTC Mar 6,2008 Some time ago, I wrote a note about using the packaged function dbms_xplan.display_cursor().  […]

    Pingback by dbms_xplan(3) « Oracle Scratchpad — March 6, 2008 @ 8:02 am GMT Mar 6,2008

  15. […] and “after” execution plans in 10.2.0.3 (pulled out of memory using the dbms_xplan.display_cursor() procedure) for an example of this type of […]

    Pingback by Cursor_sharing « Oracle Scratchpad — March 9, 2008 @ 9:14 pm GMT Mar 9,2008

  16. […] >= 11 — Last M rows, typically a bind variable order by v2.rn ; Execution Plan (10.2.0.3 – dbms_xplan.display_cursor() edited to remove columns) […]

    Pingback by Manual Optimisation - 2 « Oracle Scratchpad — May 9, 2008 @ 3:44 pm BST May 9,2008

  17. […] dbms_xplan in 10g […]

    Pingback by Page hits « Oracle Scratchpad — September 7, 2008 @ 11:30 am BST Sep 7,2008

  18. […] in the documentation here, so for more detailed explanation reading Mr.Jonathan Lewis’s post here may be good starting […]

    Pingback by On Formating Treasures of Execution Plan Interpretation « H.Tonguç Yılmaz - Oracle Blog — September 30, 2008 @ 4:37 pm BST Sep 30,2008

  19. […] dbms_xplan 10g versijā – Jonathan Lewis raksts par dbms_xplan. […]

    Pingback by SQL teikuma izpildes plāna iegūšana - Oracle, MySQL, SQL Server « Datubāzu resurss latviski — April 7, 2009 @ 6:24 am BST Apr 7,2009

  20. Hi Jonathan,

    I have one question related to the density in the CBO.
    Why we have a different density between the varchar2 and number data type?
    For exmple:

    SQL> select * from emp;
    1 aaa
    1 aaa
    1 aaa
    1 aaa
    1 aaa
    1 aaa
    1 aaa
    3 ccc
    5 eee
    1 aaa

    SQL> l
    1 select NUM_DISTINCT, DENSITY, NUM_BUCKETS, HISTOGRAM from user_tab_col_statistics
    2* where table_name = ‘EMP’
    SQL> /

    NUM_DISTINCT DENSITY NUM_BUCKETS HISTOGRAM
    ———— ———- ———– —————
    3 .05 3 FREQUENCY
    3 .333333333 1 NONE

    Comment by Kwanyoung — April 16, 2009 @ 8:09 pm BST Apr 16,2009

  21. Kwanyoung,

    In the absence of a histogram, the density is 1/num_distinct.
    In the presence of a frequency histogram the density is 1/(2 * num_rows).

    Comment by Jonathan Lewis — April 16, 2009 @ 9:58 pm BST Apr 16,2009

  22. […] then the optimizer would calcualte a cardinality of one for this predicate (having recorded a density of 1/(2 * num_rows) in the data dictionary (see comments 21 and 22 of this note on dbms_xplan). […]

    Pingback by Histogram change « Oracle Scratchpad — April 23, 2009 @ 9:25 pm BST Apr 23,2009

  23. […] Lewis @ 6:09 pm UTC May 5,2009 I’ve written several posts about dbms_xplan, and the display_cursor function in 10g. One of the nice feature of this function is that it is a “pipelined” […]

    Pingback by Dependent Plans « Oracle Scratchpad — May 5, 2009 @ 6:11 pm BST May 5,2009

  24. Jonathan, this is very handy, but it looks like we do need to totally execute the query to get the stats we need, so, what about using the “explain plan for select ….” method and generate the same info for those queries that would take too long to wait for execution ? I have a query that would take over 5 hours to run, so I don’t want to run it, I just want to see the explain plan and try to tune it form there, is there any way to use the “dbms_xplan.display_cursor(null, null, ‘ALLSTATS LAST’)” in this case? When I tried I get an error saying “cannot fetch plan for SQL_ID: 9b0mhpss56xhw, CHILD_NUMBER: 3
    Please verify value of SQL_ID and CHILD_NUMBER;
    It could also be that the plan is no longer in cursor cache (check v$sql_plan)”

    Comment by Orlando Reyes — December 15, 2009 @ 9:59 pm GMT Dec 15,2009

    • Orlando,

      If you want to see where the work is done you have to run the query, “explain plan” won’t give you execution statistics.
      11g has a new “Real-time SQL monitoring” feature that accumulates execution statistics every few seconds so that you don’t necessarily have to run the query to completion to get a good idea of where the work is going – unfortunately that doesn’t help you.

      Comment by Jonathan Lewis — December 16, 2009 @ 1:52 pm GMT Dec 16,2009

  25. Jonathan, your blog is so vital to help me get the insight of Oracle. Sorry for the long output. Did you anything wrong this explain plan? and why?

    ----------------------------------------------------------------------------------------------------------------------------------------------
    | Id  | Operation                                            | Name               | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |
    ----------------------------------------------------------------------------------------------------------------------------------------------
    |   1 |  NESTED LOOPS OUTER                                  |                    |      1 |      1 |     65 |00:02:48.23 |    3122K|    128K|
    |   2 |   NESTED LOOPS OUTER                                 |                    |      1 |      1 |     65 |00:02:48.23 |    3121K|    128K|
    |   3 |    NESTED LOOPS OUTER                                |                    |      1 |      1 |     65 |00:02:48.23 |    3121K|    128K|
    |   4 |     NESTED LOOPS OUTER                               |                    |      1 |      1 |     65 |00:02:48.23 |    3121K|    128K|
    |   5 |      NESTED LOOPS OUTER                              |                    |      1 |      1 |     65 |00:02:48.22 |    3121K|    128K|
    |   6 |       NESTED LOOPS                                   |                    |      1 |      1 |     65 |00:02:47.80 |    3121K|    128K|
    |   7 |        NESTED LOOPS OUTER                            |                    |      1 |      1 |     65 |00:02:47.80 |    3120K|    128K|
    |   8 |         NESTED LOOPS OUTER                           |                    |      1 |      1 |     65 |00:02:47.80 |    3120K|    128K|
    |   9 |          NESTED LOOPS                                |                    |      1 |      1 |     65 |00:02:47.80 |    3120K|    128K|
    |  10 |           NESTED LOOPS                               |                    |      1 |      1 |     65 |00:02:47.13 |    3120K|    128K|
    |  11 |            NESTED LOOPS OUTER                        |                    |      1 |      1 |     65 |00:02:47.13 |    3120K|    128K|
    |  12 |             NESTED LOOPS OUTER                       |                    |      1 |      1 |     65 |00:02:47.12 |    3120K|    128K|
    |  13 |              NESTED LOOPS OUTER                      |                    |      1 |      1 |     65 |00:02:47.12 |    3120K|    128K|
    |  14 |               NESTED LOOPS                           |                    |      1 |      1 |     65 |00:02:47.12 |    3120K|    128K|
    |  15 |                NESTED LOOPS OUTER                    |                    |      1 |      1 |     65 |00:02:46.67 |    3119K|    128K|
    |  16 |                 NESTED LOOPS OUTER                   |                    |      1 |      1 |     65 |00:02:46.67 |    3119K|    128K|
    |  17 |                  NESTED LOOPS OUTER                  |                    |      1 |      1 |     65 |00:02:46.67 |    3119K|    128K|
    |  18 |                   NESTED LOOPS OUTER                 |                    |      1 |      1 |     65 |00:02:46.66 |    3119K|    128K|
    |  19 |                    NESTED LOOPS OUTER                |                    |      1 |      1 |     65 |00:02:46.09 |    3119K|    128K|
    |  20 |                     NESTED LOOPS                     |                    |      1 |      1 |     65 |00:02:46.08 |    3118K|    128K|
    |  21 |                      NESTED LOOPS                    |                    |      1 |      1 |     65 |00:02:45.90 |    3118K|    127K|
    |  22 |                       NESTED LOOPS                   |                    |      1 |      1 |    120 |00:02:45.89 |    3118K|    127K|
    |  23 |                        NESTED LOOPS OUTER            |                    |      1 |      1 |    509K|00:02:07.89 |    1439K|    105K|
    |  24 |                         NESTED LOOPS OUTER           |                    |      1 |      1 |    509K|00:02:05.85 |    1439K|    105K|
    |  25 |                          NESTED LOOPS OUTER          |                    |      1 |      1 |    509K|00:02:04.32 |    1439K|    105K|
    |  26 |                           TABLE ACCESS BY INDEX ROWID| S_ORG_EXT          |      1 |      1 |    509K|00:02:02.29 |    1439K|    105K|
    |* 27 |                            INDEX SKIP SCAN           | S_ORG_EXT_M61      |      1 |      1 |    509K|00:00:03.74 |     229K|   5040 |
    |  28 |                           TABLE ACCESS BY INDEX ROWID| S_PRI_LST          |    509K|      1 |      0 |00:00:01.13 |       0 |      0 |
    |* 29 |                            INDEX UNIQUE SCAN         | S_PRI_LST_P1       |    509K|      1 |      0 |00:00:00.48 |       0 |      0 |
    |  30 |                          TABLE ACCESS BY INDEX ROWID | S_PRI_LST          |    509K|      1 |      0 |00:00:00.94 |       0 |      0 |
    |* 31 |                           INDEX UNIQUE SCAN          | S_PRI_LST_P1       |    509K|      1 |      0 |00:00:00.39 |       0 |      0 |
    |  32 |                         TABLE ACCESS BY INDEX ROWID  | S_INDUST           |    509K|      1 |      0 |00:00:01.60 |       7 |      1 |
    |* 33 |                          INDEX UNIQUE SCAN           | S_INDUST_P1        |    509K|      1 |      0 |00:00:01.06 |       7 |      1 |
    |* 34 |                        TABLE ACCESS BY INDEX ROWID   | S_ORG_BU           |    509K|      1 |    120 |00:00:37.45 |    1678K|  22662 |
    |* 35 |                         INDEX RANGE SCAN             | S_ORG_BU_U1        |    509K|      1 |    508K|00:00:09.04 |    1170K|   2392 |
    |* 36 |                       INDEX RANGE SCAN               | S_PARTY_RPT_REL_U1 |    120 |      1 |     65 |00:00:00.01 |     134 |      4 |
    |  37 |                      TABLE ACCESS BY INDEX ROWID     | S_ORG_EXT          |     65 |      1 |     65 |00:00:00.18 |     202 |     55 |
    |* 38 |                       INDEX UNIQUE SCAN              | S_ORG_EXT_U3       |     65 |      1 |     65 |00:00:00.18 |     137 |     55 |
    |  39 |                     TABLE ACCESS BY INDEX ROWID      | S_ORG_EXT          |     65 |      1 |     65 |00:00:00.01 |     202 |      0 |
    |* 40 |                      INDEX UNIQUE SCAN               | S_ORG_EXT_U3       |     65 |      1 |     65 |00:00:00.01 |     137 |      0 |
    |  41 |                    TABLE ACCESS BY INDEX ROWID       | S_CON_ADDR         |     65 |      1 |     65 |00:00:00.58 |     208 |    111 |
    |* 42 |                     INDEX RANGE SCAN                 | S_CON_ADDR_M1      |     65 |      1 |     65 |00:00:00.25 |     143 |     53 |
    |  43 |                   TABLE ACCESS BY INDEX ROWID        | S_CON_ADDR         |     65 |      1 |     65 |00:00:00.01 |     208 |      0 |
    |* 44 |                    INDEX RANGE SCAN                  | S_CON_ADDR_M1      |     65 |      1 |     65 |00:00:00.01 |     143 |      0 |
    |  45 |                  TABLE ACCESS BY INDEX ROWID         | S_CON_ADDR         |     65 |      1 |     65 |00:00:00.01 |     208 |      0 |
    |* 46 |                   INDEX RANGE SCAN                   | S_CON_ADDR_M1      |     65 |      1 |     65 |00:00:00.01 |     143 |      0 |
    |  47 |                 TABLE ACCESS BY INDEX ROWID          | S_CON_ADDR         |     65 |      1 |     65 |00:00:00.01 |     208 |      0 |
    |* 48 |                  INDEX RANGE SCAN                    | S_CON_ADDR_M1      |     65 |      1 |     65 |00:00:00.01 |     143 |      0 |
    |  49 |                TABLE ACCESS BY INDEX ROWID           | S_PARTY            |     65 |      1 |     65 |00:00:00.45 |     202 |    101 |
    |* 50 |                 INDEX UNIQUE SCAN                    | S_PARTY_P1         |     65 |      1 |     65 |00:00:00.12 |     137 |     45 |
    |  51 |               TABLE ACCESS BY INDEX ROWID            | S_ORG_EXT_X        |     65 |      1 |      0 |00:00:00.01 |       6 |      0 |
    |* 52 |                INDEX RANGE SCAN                      | S_ORG_EXT_X_U1     |     65 |      1 |      0 |00:00:00.01 |       6 |      0 |
    |  53 |              TABLE ACCESS BY INDEX ROWID             | S_ORG_EXT_SS       |     65 |      1 |      0 |00:00:00.01 |       6 |      0 |
    |* 54 |               INDEX RANGE SCAN                       | S_ORG_EXT_SS_U1    |     65 |      1 |      0 |00:00:00.01 |       6 |      0 |
    |  55 |             TABLE ACCESS BY INDEX ROWID              | S_ORG_EXT_LSX      |     65 |      1 |      0 |00:00:00.01 |      71 |      0 |
    |* 56 |              INDEX RANGE SCAN                        | S_ORG_EXT_LSX_U1   |     65 |      1 |      0 |00:00:00.01 |      71 |      0 |
    |  57 |            TABLE ACCESS BY INDEX ROWID               | S_PARTY            |     65 |      1 |     65 |00:00:00.01 |     201 |      0 |
    |* 58 |             INDEX UNIQUE SCAN                        | S_PARTY_P1         |     65 |      1 |     65 |00:00:00.01 |     136 |      0 |
    |  59 |           TABLE ACCESS BY INDEX ROWID                | S_ACCNT_POSTN      |     65 |      9 |     65 |00:00:00.67 |     207 |    133 |
    |* 60 |            INDEX RANGE SCAN                          | S_ACCNT_POSTN_U1   |     65 |      1 |     65 |00:00:00.35 |     142 |     74 |
    |  61 |          TABLE ACCESS BY INDEX ROWID                 | S_POSTN            |     65 |      1 |     65 |00:00:00.01 |     136 |      0 |
    |* 62 |           INDEX UNIQUE SCAN                          | S_POSTN_U2         |     65 |      1 |     65 |00:00:00.01 |      71 |      0 |
    |  63 |         TABLE ACCESS BY INDEX ROWID                  | S_USER             |     65 |      1 |     65 |00:00:00.01 |     201 |      0 |
    |* 64 |          INDEX UNIQUE SCAN                           | S_USER_U2          |     65 |      1 |     65 |00:00:00.01 |      71 |      0 |
    |* 65 |        INDEX UNIQUE SCAN                             | S_PARTY_P1         |     65 |      1 |     65 |00:00:00.01 |     136 |      0 |
    |  66 |       TABLE ACCESS BY INDEX ROWID                    | S_ADDR_PER         |     65 |      1 |     65 |00:00:00.42 |     201 |    105 |
    |* 67 |        INDEX UNIQUE SCAN                             | S_ADDR_PER_P1      |     65 |      1 |     65 |00:00:00.13 |     136 |     46 |
    |  68 |      TABLE ACCESS BY INDEX ROWID                     | S_ADDR_PER         |     65 |      1 |     65 |00:00:00.01 |     201 |      0 |
    |* 69 |       INDEX UNIQUE SCAN                              | S_ADDR_PER_P1      |     65 |      1 |     65 |00:00:00.01 |     136 |      0 |
    |  70 |     TABLE ACCESS BY INDEX ROWID                      | S_ADDR_PER         |     65 |      1 |     65 |00:00:00.01 |     201 |      0 |
    |* 71 |      INDEX UNIQUE SCAN                               | S_ADDR_PER_P1      |     65 |      1 |     65 |00:00:00.01 |     136 |      0 |
    |  72 |    TABLE ACCESS BY INDEX ROWID                       | S_ADDR_PER         |     65 |      1 |     65 |00:00:00.01 |     201 |      0 |
    |* 73 |     INDEX UNIQUE SCAN                                | S_ADDR_PER_P1      |     65 |      1 |     65 |00:00:00.01 |     136 |      0 |
    |  74 |   TABLE ACCESS BY INDEX ROWID                        | S_ADDR_PER         |     65 |      1 |     65 |00:00:00.01 |     201 |      0 |
    |* 75 |    INDEX UNIQUE SCAN                                 | S_ADDR_PER_P1      |     65 |      1 |     65 |00:00:00.01 |     136 |      0 |
    ----------------------------------------------------------------------------------------------------------------------------------------------
    

    Comment by Frank — March 25, 2010 @ 10:19 pm GMT Mar 25,2010

  26. Continuation from previous post …

    From line #4 to #39, could you shed some light why Starts * E-Rows is not equal to A-Rows? Is it a potential stats related issue?

    Appreciate it!

    Comment by Frank — March 25, 2010 @ 10:29 pm GMT Mar 25,2010

    • Starts * E-rows can only match A-rows where the optimizer has predicted the cardinality correctly.

      The first place (in order of execution) where the values are significantly different from each other is the first place where something is likely to be going wrong.

      In your case the first execution step is the index skip scan of S_ORG_EXT_M61 at line 27 where Oracle predicts one row and find 509,000.

      Notice that the 509,000 rows drops to 120 thanks to the access into S_ORG_BU at line 34. This suggests that it may be possible to find a different join order that avoids collecting 509,000 rows.

      Note, as a general rule, OUTER JOINs will never eliminate data from the accumulated data set, so it’s nice to postpone the nested loop outer joins until AFTER the “inner” joins that have managed to eliminate lots of data.

      Comment by Jonathan Lewis — March 26, 2010 @ 9:50 pm GMT Mar 26,2010

  27. For a minute or two this confused me

    >>The estimated values are estimates for each execution of a rowsource, the actual values are the cumulative counts.

    Then I realized you meant “cumulative” across the loops of that line. When I think cumulative, I think the columns
    cr_buffer_gets
    cu_buffer_gets
    disk_reads
    disk_writes
    elapsed_time
    which are cumulative across the children, ie the parent rows include the sum of the children, which makes it hard to scan for say which line we spent the most time on.
    Ex:

    -----------------------------------------------------------
    |Operation                  |Starts|E-Rows|A-Rows| A-Time |
    -----------------------------------------------------------
    |HASH GROUP BY              |    1 |    1 |    1 |0:04.13 |
    | FILTER                    |    1 |      | 1909 |0:04.12 |
    |  HASH JOIN                |    1 |  406 | 3413 |0:03.95 |
    |   TABLE ACCESS FULL       |    1 |   15 |   15 |0:00.01 |
    |   HASH JOIN               |    1 |  812 | 3413 |0:03.90 |
    |    TABLE ACCESS BY INDEX R|    1 |    5 |    1 |0:00.01 |
    |     INDEX RANGE SCAN      |    1 |    5 |    1 |0:00.01 |
    |    HASH JOIN              |    1 |28213 |  111K|0:03.12 |
    |     HASH JOIN             |    1 |27456 |  115K|0:01.58 |
    |      TABLE ACCESS FULL    |    1 |13679 |13679 |0:00.03 |
    |      TABLE ACCESS FULL    |    1 |27456 |  122K|0:00.37 |
    |     TABLE ACCESS FULL     |    1 |40000 |40000 |0:00.12 |
    |  SORT AGGREGATE           | 1831 |    1 | 1831 |0:00.07 |
    |   FIRST ROW               | 1831 |    1 | 1617 |0:00.04 |
    |    INDEX RANGE SCAN (MIN/M| 1831 |    1 | 1617 |0:00.02 |
    |     SORT AGGREGATE        | 1593 |    1 | 1593 |0:00.06 |
    |      FIRST ROW            | 1593 |    1 | 1593 |0:00.04 |
    |       INDEX RANGE SCAN (MI| 1593 |    1 | 1593 |0:00.02 |
    

    Which it makes it easy to see that the “A-time” includes the sum of the time for the children, ie the cumulative time of the children. Put a script up to show Wolfgang’s TCF ratios and Christian Antognini’s LIO per row as well as the per row elapsed time: http://sites.google.com/site/embtdbo/tuner/oracle-tcf-query-and-lios-per-row

    Comment by Kyle Hailey — May 30, 2010 @ 12:42 pm BST May 30,2010

    • the below query took 34 min, but why the execution plan is showing different timings, stats are upto date on the tables::::

      PLAN_TABLE_OUTPUT
      Plan hash value: 1046889487
       
      ----------------------------------------------------------------------------------------------------------------------
      | Id  | Operation                    | Name             | Rows  | Cost (%CPU)| Time     |    TQ  |IN-OUT| PQ Distrib |
      ----------------------------------------------------------------------------------------------------------------------
      |   0 | SELECT STATEMENT             |                  |  2758K|   607K  (1)| 02:01:30 |        |      |            |
      |   1 |  PX COORDINATOR              |                  |       |            |          |        |      |            |
      |   2 |   PX SEND QC (RANDOM)        | :TQ10002         |  2758K|   607K  (1)| 02:01:30 |  Q1,02 | P->S | QC (RAND)  |
      |*  3 |    HASH JOIN                 |                  |  2758K|   607K  (1)| 02:01:30 |  Q1,02 | PCWP |            |
      |   4 |     PX RECEIVE               |                  |  2758K| 44053   (2)| 00:08:49 |  Q1,02 | PCWP |            |
      |   5 |      PX SEND HASH            | :TQ10001         |  2758K| 44053   (2)| 00:08:49 |  Q1,01 | P->P | HASH       |
      |   6 |       PX BLOCK ITERATOR      |                  |  2758K| 44053   (2)| 00:08:49 |  Q1,01 | PCWC |            |
      |*  7 |        TABLE ACCESS FULL     | OI_PAYMENT       |  2758K| 44053   (2)| 00:08:49 |  Q1,01 | PCWP |            |
      |   8 |     BUFFER SORT              |                  |       |            |          |  Q1,02 | PCWC |            |
      |   9 |      PX RECEIVE              |                  |    31M|   563K  (1)| 01:52:41 |  Q1,02 | PCWP |            |
      |  10 |       PX SEND HASH           | :TQ10000         |    31M|   563K  (1)| 01:52:41 |        | S->P | HASH       |
      |* 11 |        VIEW                  | index$_join$_003 |    31M|   563K  (1)| 01:52:41 |        |      |            |
      |* 12 |         HASH JOIN            |                  |       |            |          |        |      |            |
      |  13 |          INLIST ITERATOR     |                  |       |            |          |        |      |            |
      |* 14 |           INDEX RANGE SCAN   | TC_OICASE1       |    31M|   505M (87)|999:59:59 |        |      |            |
      |  15 |          INDEX FAST FULL SCAN| PK_OI_CASE       |    31M|   369K  (1)| 01:13:59 |        |      |            |
      ----------------------------------------------------------------------------------------------------------------------
       
      Predicate Information (identified by operation id):
      ---------------------------------------------------
       
         3 - access("OI_PAYMENT"."ACCOUNTNUMBER"="OI_CASE"."ACCOUNTNUMBER")
         7 - filter("OI_PAYMENT"."DATEOFRECORD">=TO_DATE(' 2010-10-26 05:00:00', 'syyyy-mm-dd hh24:mi:ss') AND 
                    "OI_PAYMENT"."DATEOFRECORD"<TO_DATE(' 2010-10-29 04:53:00', 'syyyy-mm-dd hh24:mi:ss'))
        11 - filter("CCI"='1' OR "CCI"='2')
        12 - access(ROWID=ROWID)
        14 - access("CCI"='1' OR "CCI"='2')
      

      Comment by abhinav — November 4, 2010 @ 9:16 pm GMT Nov 4,2010

      • Abhinav,

        Consider this analogy:

        It takes 67 minutes to drive from Heathrow to Gatwick when travelling at the legal limit during off-peak hours. During peak periods in bad weather it can take more than two hours; at 3 a.m. on a clear night and driving dangerously all the way it takes 42 minutes.

        How long does it take to drive from Heathrow to Gatwick – you are only allowed to give me one answer in minutes ?

        Oracle has a model – it is rarely a perfect match for the real world.

        Comment by Jonathan Lewis — November 8, 2010 @ 6:26 pm GMT Nov 8,2010


RSS feed for comments on this post.

Website Powered by WordPress.com.