I ORDERED a Hint – Why Won’t You Listen to Me?

29 11 2010

November 29, 2010 (Updated November 30, 2010)

I recently read a blog article that forced me to Stop, Think, … Understand (which happens to be the subtitle of this blog, so it is worth mentioning).  The blog article discussed an error found in the Oracle Database documentation regarding how to read an execution plan – more specifically, how to find the first operation in the execution plan.  A couple of months ago I had the opportunity to attend one of Tanel Poder’s presentations, which I believe was titled “Back to Basics – Choosing the Starting Point of Performance Tuning and Troubleshooting Wisely.”  In the presentation Tanel remarked that there is an error in the documentation (quoted on the referenced blog article), which essentially states that the first operation executed in an execution plan is the operation that is indented the most to the right.  Tanel made the claim that (paraphrasing, of course) the first operation that is executed is actually the first operation (reading from the top of the execution plan) which has no child operations.  An interesting claim, with which I felt no doubt that is correct, but I never verified the claim.  I had that chance when reviewing the referenced blog article, where one of the comments smartly suggested to test with the ORDERED clause hint, and to examine the execution plan.  It seemed to me that this was a very good idea, and I was initially shocked to find that Tanel’s claim was incorrect.  But wait, we can’t stop yet.  What else can we test to see if Tanel is right (he is, of course – see the referenced blog article for the reason)?  How about a 10046 trace with the ORDERED clause hint?  But then I started seeing something strange, a quick script that uses the test tables that were created in an earlier blog article:

SET AUTOTRACE TRACEONLY STATISTICS
SET ARRAYSIZE 1000

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

ALTER SESSION SET TRACEFILE_IDENTIFIER = 'ORDERED_POL_PO_P';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';

SELECT /*+ ORDERED */
  PO.VENDOR_ID,
  P.PRODUCT_CODE,
  P.STOCK_UM,
  SUM(POL.ORDER_QTY) ORDER_QTY
FROM
  PO_LINE POL,
  PO_HEADER PO,
  PARTS P
WHERE
  PO.ORDER_DATE BETWEEN TRUNC(SYSDATE-90) AND TRUNC(SYSDATE)
  AND PO.PURC_ORDER_ID=POL.PURC_ORDER_ID
  AND POL.PART_ID=P.PART_ID
GROUP BY
  PO.VENDOR_ID,
  P.PRODUCT_CODE,
  P.STOCK_UM;

ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

ALTER SESSION SET TRACEFILE_IDENTIFIER = 'ORDERED_POL_P_PO';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';

SELECT /*+ ORDERED */
  PO.VENDOR_ID,
  P.PRODUCT_CODE,
  P.STOCK_UM,
  SUM(POL.ORDER_QTY) ORDER_QTY
FROM
  PO_LINE POL,
  PARTS P,
  PO_HEADER PO
WHERE
  PO.ORDER_DATE BETWEEN TRUNC(SYSDATE-90) AND TRUNC(SYSDATE)
  AND PO.PURC_ORDER_ID=POL.PURC_ORDER_ID
  AND POL.PART_ID=P.PART_ID
GROUP BY
  PO.VENDOR_ID,
  P.PRODUCT_CODE,
  P.STOCK_UM;

SELECT SYSDATE FROM DUAL;

ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

ALTER SESSION SET TRACEFILE_IDENTIFIER = 'ORDERED_P_POL_PO';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';

SELECT /*+ ORDERED */
  PO.VENDOR_ID,
  P.PRODUCT_CODE,
  P.STOCK_UM,
  SUM(POL.ORDER_QTY) ORDER_QTY
FROM
  PARTS P,
  PO_LINE POL,
  PO_HEADER PO
WHERE
  PO.ORDER_DATE BETWEEN TRUNC(SYSDATE-90) AND TRUNC(SYSDATE)
  AND PO.PURC_ORDER_ID=POL.PURC_ORDER_ID
  AND POL.PART_ID=P.PART_ID
GROUP BY
  PO.VENDOR_ID,
  P.PRODUCT_CODE,
  P.STOCK_UM;

SELECT SYSDATE FROM DUAL;

ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

ALTER SESSION SET TRACEFILE_IDENTIFIER = 'ORDERED_P_PO_POL';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';

SELECT /*+ ORDERED */
  PO.VENDOR_ID,
  P.PRODUCT_CODE,
  P.STOCK_UM,
  SUM(POL.ORDER_QTY) ORDER_QTY
FROM
  PARTS P,
  PO_HEADER PO,
  PO_LINE POL
WHERE
  PO.ORDER_DATE BETWEEN TRUNC(SYSDATE-90) AND TRUNC(SYSDATE)
  AND PO.PURC_ORDER_ID=POL.PURC_ORDER_ID
  AND POL.PART_ID=P.PART_ID
GROUP BY
  PO.VENDOR_ID,
  P.PRODUCT_CODE,
  P.STOCK_UM;

SELECT SYSDATE FROM DUAL;

ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF'; 

So, what is strange about the 10046 trace file.  Let’s take a look at the TKPROF output that was generated by Oracle Database 11.2.0.1 for the first SQL statement (color coded to help see the tables in the execution plan):  

SELECT /*+ ORDERED */
FROM
  PO_LINE POL,
  PO_HEADER PO,
  PARTS P

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
      1855       1855       1855  HASH GROUP BY (cr=267225 pr=267202 pw=0 time=397 us cost=21234 size=105735 card=1855)
      5935       5935       5935   HASH JOIN  (cr=267225 pr=267202 pw=0 time=757 us cost=21233 size=338295 card=5935)
      5935       5935       5935    VIEW  VW_GBC_9 (cr=262229 pr=262213 pw=0 time=1641 us cost=20837 size=213660 card=5935)
      5935       5935       5935     HASH GROUP BY (cr=262229 pr=262213 pw=0 time=757 us cost=20837 size=308620 card=5935)
    329789     329789     329789      FILTER  (cr=262229 pr=262213 pw=0 time=4290315 us)
    329789     329789     329789       HASH JOIN  (cr=262229 pr=262213 pw=0 time=4248980 us cost=20823 size=17880824 card=343862)
     13890      13890      13890        TABLE ACCESS FULL PO_HEADER (cr=13173 pr=13163 pw=0 time=552501 us cost=1068 size=388920 card=13890)
  12205347   12205347   12205347        TABLE ACCESS FULL PO_LINE (cr=249056 pr=249050 pw=0 time=2448109 us cost=19697 size=292928328 card=12205347)
     99694      99694      99694    TABLE ACCESS FULL PARTS (cr=4996 pr=4989 pw=0 time=43511 us cost=394 size=2093574 card=99694) 

In the above, Oracle builds a hash table (this probably is not the right term, which escapes me at the moment) of the PO_HEADER table which is then used to probe into the 1.2 million rows in the PO_LINE table, eventually the 5935 rows from the join of PO_HEADER to PO_LINE is joined to the PARTS table.  So, other than the order of PO_HEADER and PO_LINE being swapped, the ORDERED hint seems to have controlled the order in which the tables were accessed.  Let’s take a look at the next query:

SELECT /*+ ORDERED */
FROM
  PO_LINE POL,
  PARTS P,
  PO_HEADER PO

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
      1855       1855       1855  HASH GROUP BY (cr=267225 pr=317918 pw=50685 time=529 us cost=26617 size=135415 card=1855)
    329789     329789     329789   FILTER  (cr=267225 pr=317918 pw=50685 time=3703300 us)
    329789     329789     329789    HASH JOIN  (cr=267225 pr=317918 pw=50685 time=3669899 us cost=26602 size=25101926 card=343862)
     13890      13890      13890     TABLE ACCESS FULL PO_HEADER (cr=13173 pr=13163 pw=0 time=546640 us cost=1068 size=388920 card=13890)
  12205347   12205347   12205347     HASH JOIN  (cr=254052 pr=304755 pw=50685 time=3243495 us cost=25476 size=549240615 card=12205347)
  12205347   12205347   12205347      TABLE ACCESS FULL PO_LINE (cr=249056 pr=249050 pw=0 time=1831025 us cost=19697 size=292928328 card=12205347)
     99694      99694      99694      TABLE ACCESS FULL PARTS (cr=4996 pr=4989 pw=0 time=50678 us cost=394 size=2093574 card=99694) 

The above might give us a little trouble.  It looks like Oracle builds a hash table (this probably is not the right term, which escapes me at the moment) of the 1.2 million rows in the PO_LINE table which is then used to probe into the nearly 100,000 rows in the PARTS table, and then that result is hash joined to the PO_HEADER table.  So, the ORDERED hint seems to have exactly controlled the order in which the tables were accessed (but wait, something is wrong, if only I knew how to read the raw 10046 trace file).  Let’s check the next query’s TKPROF output: 

SELECT /*+ ORDERED */
FROM
  PARTS P,
  PO_LINE POL,
  PO_HEADER PO

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
      1855       1855       1855  HASH GROUP BY (cr=267225 pr=267202 pw=0 time=397 us cost=26588 size=135415 card=1855)
    329789     329789     329789   FILTER  (cr=267225 pr=267202 pw=0 time=6561463 us)
    329789     329789     329789    HASH JOIN  (cr=267225 pr=267202 pw=0 time=6525886 us cost=26574 size=25101926 card=343862)
     13890      13890      13890     TABLE ACCESS FULL PO_HEADER (cr=13173 pr=13163 pw=0 time=532624 us cost=1068 size=388920 card=13890)
  12205347   12205347   12205347     HASH JOIN  (cr=254052 pr=254039 pw=0 time=6233040 us cost=25447 size=549240615 card=12205347)
     99694      99694      99694      TABLE ACCESS FULL PARTS (cr=4996 pr=4989 pw=0 time=42487 us cost=394 size=2093574 card=99694)
  12205347   12205347   12205347      TABLE ACCESS FULL PO_LINE (cr=249056 pr=249050 pw=0 time=1623411 us cost=19697 size=292928328 card=12205347)

The join order is PARTS -> PO_LINE -> PO_HEADER, just like what we ORDERED (but wait, what does that 10046 trace file show again?).  Let’s take a look at the final query’s TKPROF output:

SELECT /*+ ORDERED */
  PO.VENDOR_ID,
  P.PRODUCT_CODE,
  P.STOCK_UM,
  SUM(POL.ORDER_QTY) ORDER_QTY
FROM
  PARTS P,
  PO_HEADER PO,
  PO_LINE POL

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
      1855       1855       1855  HASH GROUP BY (cr=267225 pr=284314 pw=17112 time=794 us cost=78881 size=109445 card=1855)
    103059     103059     103059   MERGE JOIN  (cr=267225 pr=284314 pw=17112 time=2531825 us cost=78877 size=6031275 card=102225)
   3628420    3628420    3628420    SORT JOIN (cr=254052 pr=271151 pw=17112 time=930143 us cost=77807 size=112482384 card=3628464)
   3628464    3628464    3628464     VIEW  VW_GBC_9 (cr=254052 pr=257294 pw=3255 time=1181413 us cost=77807 size=112482384 card=3628464)
   3628464    3628464    3628464      HASH GROUP BY (cr=254052 pr=257294 pw=3255 time=702832 us cost=77807 size=163280880 card=3628464)
  12205347   12205347   12205347       FILTER  (cr=254052 pr=254039 pw=0 time=7536710 us)
  12205347   12205347   12205347        HASH JOIN  (cr=254052 pr=254039 pw=0 time=6162000 us cost=25447 size=549240615 card=12205347)
     99694      99694      99694         TABLE ACCESS FULL PARTS (cr=4996 pr=4989 pw=0 time=45175 us cost=394 size=2093574 card=99694)
  12205347   12205347   12205347         TABLE ACCESS FULL PO_LINE (cr=249056 pr=249050 pw=0 time=1711986 us cost=19697 size=292928328 card=12205347)
    103059     103059     103059    SORT JOIN (cr=13173 pr=13163 pw=0 time=0 us cost=1070 size=388920 card=13890)
     13890      13890      13890     TABLE ACCESS FULL PO_HEADER (cr=13173 pr=13163 pw=0 time=550208 us cost=1068 size=388920 card=13890) 

The join order is PARTS -> PO_LINE -> PO_HEADER.  What?  I thought that I requested, no DEMANDED (hints are directives after all) that we join in this order:
PARTS -> PO_HEADER -> PO_LINE

I guess that I need to check the documentation for the ORDERED hint: 

“The ORDERED hint instructs Oracle to join tables in the order in which they appear in the FROM clause. Oracle recommends that you use the LEADING hint, which is more versatile than the ORDERED hint.

When you omit the ORDERED hint from a SQL statement requiring a join, the optimizer chooses the order in which to join the tables. You might want to use the ORDERED hint to specify a join order if you know something that the optimizer does not know about the number of rows selected from each table. Such information lets you choose an inner and outer table better than the optimizer could.”

OK, so the documentation confirms that the ORDERED hint controls the join order, not the order in which the tables are accessed.  So, how can we explain why the optimizer did not do as we instructed, with a specific join order?  We could create a 10053 trace file for the query:

ALTER SESSION SET TRACEFILE_IDENTIFIER = 'ORDERED_P_PO_POL_FIND_ME';
ALTER SESSION SET EVENTS '10053 TRACE NAME CONTEXT FOREVER, LEVEL 1';

SELECT /*+ ORDERED */ /* FIND_ME */
  PO.VENDOR_ID,
  P.PRODUCT_CODE,
  P.STOCK_UM,
  SUM(POL.ORDER_QTY) ORDER_QTY
FROM
  PARTS P,
  PO_HEADER PO,
  PO_LINE POL
WHERE
  PO.ORDER_DATE BETWEEN TRUNC(SYSDATE-90) AND TRUNC(SYSDATE)
  AND PO.PURC_ORDER_ID=POL.PURC_ORDER_ID
  AND POL.PART_ID=P.PART_ID
GROUP BY
  PO.VENDOR_ID,
  P.PRODUCT_CODE,
  P.STOCK_UM;
ALTER SESSION SET EVENTS '10053 TRACE NAME CONTEXT OFF';

Taking a look inside the 10053 trace file, we find the execution plan with the Predicate Information section:

============
Plan Table
============
---------------------------------------------+-----------------------------------+
| Id  | Operation                 | Name     | Rows  | Bytes | Cost  | Time      |
---------------------------------------------+-----------------------------------+
| 0   | SELECT STATEMENT          |          |       |       |  125K |           |
| 1   |  HASH GROUP BY            |          |  168K | 9936K |  125K |  00:17:04 |
| 2   |   MERGE JOIN              |          |  548K |   32M |  122K |  00:17:39 |
| 3   |    SORT JOIN              |          | 9629K |  292M |  121K |  00:16:29 |
| 4   |     VIEW                  | VW_GBC_9 | 9629K |  292M |  121K |  00:16:29 |
| 5   |      HASH GROUP BY        |          | 9629K |  423M |  121K |  00:16:29 |
| 6   |       FILTER              |          |       |       |       |           |
| 7   |        HASH JOIN          |          |   12M |  524M |   25K |  00:03:24 |
| 8   |         TABLE ACCESS FULL | PARTS    |   97K | 2045K |   394 |  00:00:04 |
| 9   |         TABLE ACCESS FULL | PO_LINE  |   12M |  279M |   19K |  00:03:38 |
| 10  |    SORT JOIN              |          |   27K |  767K |  1251 |  00:00:11 |
| 11  |     TABLE ACCESS FULL     | PO_HEADER|   27K |  767K |  1068 |  00:00:09 |
---------------------------------------------+-----------------------------------+
Predicate Information:
----------------------
6 - filter(TRUNC(SYSDATE@!-90)<=TRUNC(SYSDATE@!))
7 - access("POL"."PART_ID"="P"."PART_ID")
10 - access("PO"."PURC_ORDER_ID"="ITEM_1")
10 - filter("PO"."PURC_ORDER_ID"="ITEM_1")
11 - filter(("PO"."ORDER_DATE"<=TRUNC(SYSDATE@!) AND "PO"."ORDER_DATE">=TRUNC(SYSDATE@!-90))) 

ITEM_1?  Someone’s been rewriting my SQL statement?  Let’s look a little further up the trace file (the query text printed in the 10053 trace file has been reformatted with extra line breaks and spaces):

Final query after transformations:******* UNPARSED QUERY IS *******
SELECT /*+ ORDERED */
  "PO"."VENDOR_ID" "VENDOR_ID",
  "VW_GBC_9"."ITEM_3" "PRODUCT_CODE",
  "VW_GBC_9"."ITEM_4" "STOCK_UM",
  SUM("VW_GBC_9"."ITEM_2") "ORDER_QTY"
FROM
  (SELECT
     "POL"."PURC_ORDER_ID" "ITEM_1",
     SUM("POL"."ORDER_QTY") "ITEM_2",
     "P"."PRODUCT_CODE" "ITEM_3",
     "P"."STOCK_UM" "ITEM_4"
   FROM
     "TESTUSER"."PO_LINE" "POL",
     "TESTUSER"."PARTS" "P"
   WHERE
     "POL"."PART_ID"="P"."PART_ID"
      AND TRUNC(SYSDATE@!-90)<=TRUNC(SYSDATE@!)
   GROUP BY
    "POL"."PURC_ORDER_ID","P"."PRODUCT_CODE","P"."STOCK_UM") "VW_GBC_9",
  "TESTUSER"."PO_HEADER" "PO"
WHERE
  "PO"."ORDER_DATE">=TRUNC(SYSDATE@!-90)
  AND "PO"."ORDER_DATE"<=TRUNC(SYSDATE@!)
  AND "PO"."PURC_ORDER_ID"="VW_GBC_9"."ITEM_1"
GROUP BY
  "PO"."VENDOR_ID",
  "VW_GBC_9"."ITEM_3",
  "VW_GBC_9"."ITEM_4"
kkoqbc: optimizing query block SEL$6E4193EC (#2) 

Well, I guess that explains why my ORDERED hint did not behave as expected.  Darn optimizer completely rewrote the SQL statement before the ORDERED hint was applied.  Now I am starting to wonder how this query might perform in Oracle Database 10.2.0.5, since the hinted query was affected by an automatic transformation performed by the optimizer.

————-

Now, back to demonstrate that Tanel’s claim is correct.  First, let’s find the OBJECT_IDs for the tables involved in the query:

SQL> SELECT OBJECT_NAME FROM DBA_OBJECTS WHERE OBJECT_ID=82052;

OBJECT_NAME
---------------------------------------------------------------
PARTS

SQL> SELECT OBJECT_NAME FROM DBA_OBJECTS WHERE OBJECT_ID=82062;

OBJECT_NAME
---------------------------------------------------------------
PO_HEADER

SQL> SELECT OBJECT_NAME FROM DBA_OBJECTS WHERE OBJECT_ID=82069;

OBJECT_NAME
---------------------------------------------------------------
PO_LINE 

From the above, we see that PARTS=82052, PO_HEADER=82062, and PO_LINE=82069.  Now what?  Let’s check the raw 10046 trace file for the second of our test queries that generated the following TKPROF output:

SELECT /*+ ORDERED */
FROM
  PO_LINE POL,
  PARTS P,
  PO_HEADER PO

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
      1855       1855       1855  HASH GROUP BY (cr=267225 pr=317918 pw=50685 time=529 us cost=26617 size=135415 card=1855)
    329789     329789     329789   FILTER  (cr=267225 pr=317918 pw=50685 time=3703300 us)
    329789     329789     329789    HASH JOIN  (cr=267225 pr=317918 pw=50685 time=3669899 us cost=26602 size=25101926 card=343862)
     13890      13890      13890     TABLE ACCESS FULL PO_HEADER (cr=13173 pr=13163 pw=0 time=546640 us cost=1068 size=388920 card=13890)
  12205347   12205347   12205347     HASH JOIN  (cr=254052 pr=304755 pw=50685 time=3243495 us cost=25476 size=549240615 card=12205347)
  12205347   12205347   12205347      TABLE ACCESS FULL PO_LINE (cr=249056 pr=249050 pw=0 time=1831025 us cost=19697 size=292928328 card=12205347)
     99694      99694      99694      TABLE ACCESS FULL PARTS (cr=4996 pr=4989 pw=0 time=50678 us cost=394 size=2093574 card=99694)  

------

PARSING IN CURSOR #3 len=338 dep=0 uid=286 oct=3 lid=286 tim=4471668209 hv=2860598711 ad='469666838' sqlid='2fhf2v2p82jdr'
SELECT /*+ ORDERED */
  PO.VENDOR_ID,
  P.PRODUCT_CODE,
  P.STOCK_UM,
  SUM(POL.ORDER_QTY) ORDER_QTY
FROM
  PO_LINE POL,
  PARTS P,
  PO_HEADER PO
WHERE
  PO.ORDER_DATE BETWEEN TRUNC(SYSDATE-90) AND TRUNC(SYSDATE)
  AND PO.PURC_ORDER_ID=POL.PURC_ORDER_ID
  AND POL.PART_ID=P.PART_ID
GROUP BY
  PO.VENDOR_ID,
  P.PRODUCT_CODE,
  P.STOCK_UM
END OF STMT
PARSE #3:c=0,e=43,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4284856579,tim=4471668208
EXEC #3:c=0,e=47,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4284856579,tim=4471668337
WAIT #3: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=4471668363
WAIT #3: nam='db file sequential read' ela= 359 file#=1 block#=536704 blocks=1 obj#=82062 tim=4471668787
WAIT #3: nam='db file scattered read' ela= 596 file#=1 block#=536705 blocks=7 obj#=82062 tim=4471669513
WAIT #3: nam='db file scattered read' ela= 564 file#=1 block#=536752 blocks=8 obj#=82062 tim=4471670343
WAIT #3: nam='db file scattered read' ela= 470 file#=1 block#=536760 blocks=8 obj#=82062 tim=4471671092
WAIT #3: nam='db file scattered read' ela= 639 file#=1 block#=536768 blocks=8 obj#=82062 tim=4471671970
...
WAIT #3: nam='db file scattered read' ela= 408 file#=1 block#=558336 blocks=128 obj#=82062 tim=4472034957
WAIT #3: nam='db file scattered read' ela= 334 file#=1 block#=558464 blocks=107 obj#=82062 tim=4472036641
WAIT #3: nam='db file sequential read' ela= 357 file#=1 block#=96384 blocks=1 obj#=82069 tim=4472040086
WAIT #3: nam='direct path read' ela= 385 file number=1 first dba=96385 block cnt=7 obj#=82069 tim=4472040755
WAIT #3: nam='direct path read' ela= 186 file number=1 first dba=96456 block cnt=8 obj#=82069 tim=4472045786
WAIT #3: nam='direct path read' ela= 611 file number=1 first dba=96496 block cnt=24 obj#=82069 tim=4472046904
...
WAIT #3: nam='direct path read' ela= 1104 file number=1 first dba=1342848 block cnt=128 obj#=82069 tim=4478002620
WAIT #3: nam='direct path write temp' ela= 1601 file number=201 first dba=245981 block cnt=31 obj#=82069 tim=4478004794
WAIT #3: nam='direct path write temp' ela= 1985 file number=201 first dba=246016 block cnt=31 obj#=82069 tim=4478017466
WAIT #3: nam='direct path write temp' ela= 2423 file number=201 first dba=245725 block cnt=31 obj#=82069 tim=4478023049
WAIT #3: nam='direct path write temp' ela= 441 file number=201 first dba=245791 block cnt=31 obj#=82069 tim=4478027519
WAIT #3: nam='direct path write temp' ela= 2985 file number=201 first dba=245950 block cnt=31 obj#=82069 tim=4478030913
WAIT #3: nam='asynch descriptor resize' ela= 4 outstanding #aio=1 current aio limit=4294967295 new aio limit=511 obj#=82069 tim=4478044778
WAIT #3: nam='db file sequential read' ela= 28370 file#=1 block#=515584 blocks=1 obj#=82052 tim=4478077091
WAIT #3: nam='db file scattered read' ela= 503 file#=1 block#=515585 blocks=7 obj#=82052 tim=4478077765
WAIT #3: nam='direct path read temp' ela= 806 file number=201 first dba=288671 block cnt=31 obj#=82052 tim=4478097288
WAIT #3: nam='direct path read temp' ela= 467 file number=201 first dba=288702 block cnt=31 obj#=82052 tim=4478098147
WAIT #3: nam='direct path read temp' ela= 435 file number=201 first dba=288733 block cnt=31 obj#=82052 tim=4478099041
... 

Repeating what we found earlier: PARTS=82052, PO_HEADER=82062, and PO_LINE=82069.  We see that Oracle Database's runtime engine accessed the PO_HEADER table first, and then the PO_LINE table, and then finally the PARTS table, just as Tanel had claimed would happen.

But what is that 'asynch descriptor resize' wait event?  Could Tanel Poder have already answered that question?

--------------

Edit November 30, 2010:

Summarizing the comments so far:

  • When unnesting a subquery, optimizer performs the unnest operation *before* appying the ORDERED hint. (Tanel Poder)
  • Outline directives use the LEADING hint and not the ORDERED hint. (Greg Rahn)
  • The LEADING hint should be used when possible rather than the ORDERED hint - the differences with the ORDERED hint may not be exposed until an upgrade is performed.
  • On Oracle Database 10.2.0.5 the execution plans are identical for the ORDERED and LEADING hint versions of the four SQL statements, including the one with the intentional Cartesian join (the GBP entries that appear to be associated with Cost-Based Group-By/Distinct Placement do not appear in 10053 trace files on 10.2.0.5).
  • On Oracle Database 11.1.0.7 the execution plans are identical for the ORDERED and LEADING hint versions of the first three SQL statements (and identical to 10.2.0.5), while the ORDERED version of the last SQL statement (with the intentional Cartesian join) was transformed into a different SQL statement in a section of the 10053 trace file called "Cost-Based Group By Placement"
  • On Oracle Database 11.2.0.1 the execution plans are identical for the ORDERED and LEADING hint versions of the first three SQL statements (and identical to 10.2.0.5), while the ORDERED version of the last SQL statement (with the intentional Cartesian join) was transformed into a different SQL statement (identical to 11.1.0.7) in a section of the 10053 trace file called "Cost-Based Group-By/Distinct Placement"
  • On Oracle Database 11.2.0.1 the execution plans for the SQL statements could potentially change on future executions due to the effects of Cardinality Feedback
  • On Oracle Database 11.2.0.1 when the execution plans for the SQL statements change due to Cardinality Feedback, SET AUTOTRACE TRACEONLY EXPLAIN continues to show the original execution plan even after 10046 trace files show that the runtime engine is using the execution plan developed as a result of Cardinality Feedback.
  • For execution plans affected by Cardinality Feedback, the "Content of other_xml column" portion of a 10053 trace (just below the printed execution plan) will show "cardinality_feedback: yes".

Just wondering if anyone noticed that on my laptop (used for this blog article) I apparently created the objects in the SYSTEM tablespace while connected as the TESTUSER (I did not set the default tablespace for the TESTUSER, and apparently did not set a system-wide default).  How would I know that from the above blog article alone?








Follow

Get every new post delivered to your Inbox.

Join 142 other followers