May 10, 2010
It is a bit curious to see the number of message threads discussing calculated query costs that appeared last week on the OTN forums:
- Oracle Selects a Plan with Higher Cost? – an interesting thread where Jonathan Lewis demonstrates that using an index hint in a query is actually a directive and not just a suggestion to the query optimizer as would be implied by the common English definition of the term “hint“. Jonathan’s test case showed that that using the hint did not lower the calculated cost of the index access as stated in a 2001 thread on asktom.oracle.com, but instead restricted the access paths that were available to the optimizer, assuming that the index hint was valid.
- Cost in explain plan vs elapsed time – the calculated cost for accessing a partitioned table is higher than that for an equivalent unpartitioned table, yet the ELAPSED_TIME in V$SQLAREA is less for the query accessing the partitioned table.
- Different cost value ,but have the same execute time – changing the CPU cost and IO cost for a function decreased the cost of a query from 141 to 115, yet the query still takes just as long to execute.
- About cost in tkprof – I offered a couple of test cases that showed why one should not bother to determine the calculated query cost once a TKPROF summary is generated from a 10046 trace of the query execution.
There have been other OTN threads that discussed query costs, and that OTN thread lead to an earlier blog article on this site.
My responses in the About cost in tkprof thread follow – maybe someone will find the information to be helpful:
Oracle Database 11.1.0.6 and higher will output the calculated cost for a line in the execution plan when the STAT lines are written to the 10046 trace file. These STAT lines are then read by TKPROF and output in the “Row Source Operation” section of the output. In the case of 11.1.0.6 and greater, this is the estimated cost for the actual execution plan used by the query. Autotrace shows the estimated cost for what might be the execution plan that will be used by the query (see this blog article). Prior to Oracle Database 11.1.0.6, the calculated, estimated cost was not written to the trace file. The hash value and SQL ID (starting with 11.1.0.6) will be written to the raw 10046 trace file – you can use that information to pull the actual execution plan with cost figures from the library cache along with estimated costs using DBMS_XPLAN.DISPLAY_CURSOR (assuming that you are running Oracle Database 10g R1 or higher). See this three part series for details.
The estimated cost figure has a very limited value outside of its intended use by Oracle’s query optimizer as a means to derive the individual steps within a specific execution plan. You should not use the estimated cost figures as a means to determine if one query is more efficient than another query.
There is a reason why I did not suggest using the EXPLAIN parameter of TKPROF. The main reason is that it may show a very different execution plan. Secondly, it apparently does not include any COST values for Oracle 10.2.0.x. Third, I recommended against using the calculated cost values for comparisons. A demonstration is necessary:
CREATE TABLE T1(
C1 NUMBER,
C2 VARCHAR2(255),
PRIMARY KEY (C1));
CREATE TABLE T2(
C1 NUMBER,
C2 VARCHAR2(255),
PRIMARY KEY (C1));
INSERT INTO
T1
SELECT
ROWNUM,
LPAD('A',255,'A')
FROM
(SELECT
ROWNUM RN
FROM
DUAL
CONNECT BY
LEVEL<=10000) V1,
(SELECT
ROWNUM RN
FROM
DUAL
CONNECT BY
LEVEL<=30) V2;
INSERT INTO
T2
SELECT
ROWNUM,
LPAD('A',255,'A')
FROM
(SELECT
ROWNUM RN
FROM
DUAL
CONNECT BY
LEVEL<=10000) V1,
(SELECT
ROWNUM RN
FROM
DUAL
CONNECT BY
LEVEL<=30) V2;
COMMIT;
EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1',CASCADE=>TRUE)
EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T2',CASCADE=>TRUE)
We now have two tables, each with 300,000 rows – each of the tables has a primary key index. The test case continues:
VARIABLE N1 NUMBER VARIABLE N2 NUMBER EXEC :N1:=1 EXEC :N2:=100000 SET AUTOTRACE TRACEONLY STATISTICS ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 4'; ALTER SESSION SET TRACEFILE_IDENTIFIER = 'EXPLAIN_PLAN_TEST'; SELECT T1.C1, T2.C1, SUBSTR(T1.C2,1,1) T1_C2, SUBSTR(T2.C2,1,1) T2_C2 FROM T1, T2 WHERE T1.C1=T2.C1 AND T1.C1 BETWEEN :N1 AND :N2; EXEC :N2:=10 SELECT T1.C1, T2.C1, SUBSTR(T1.C2,1,1) T1_C2, SUBSTR(T2.C2,1,1) T2_C2 FROM T1, T2 WHERE T1.C1=T2.C1 AND T1.C1 BETWEEN :N1 AND :N2; ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';
The output of the above is the following:
100000 rows selected. Statistics --------------------------------------------------- 45 recursive calls 0 db block gets 24673 consistent gets 26419 physical reads 0 redo size 2051555 bytes sent via SQL*Net to client 73660 bytes received via SQL*Net from client 6668 SQL*Net roundtrips to/from client 0 sorts (memory) 0 sorts (disk) 100000 rows processed 10 rows selected. Statistics --------------------------------------------------- 0 recursive calls 0 db block gets 22257 consistent gets 20896 physical reads 0 redo size 605 bytes sent via SQL*Net to client 334 bytes received via SQL*Net from client 2 SQL*Net roundtrips to/from client 0 sorts (memory) 0 sorts (disk) 10 rows processed
Now we have a 10046 trace file, move it back to the client PC, and process the trace file using TKPROF with the EXPLAIN option (not recommended for typical use).
exit TKPROF test_ora_2392_explain_plan_test.trc test_ora_2392_explain_plan_test.txt EXPLAIN=testuser/testpass@test
So, what does the resulting TKPROF summary file show?
SELECT T1.C1, T2.C1, SUBSTR(T1.C2,1,1) T1_C2, SUBSTR(T2.C2,1,1) T2_C2 FROM T1, T2 WHERE T1.C1=T2.C1 AND T1.C1 BETWEEN :N1 AND :N2 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 2 0.00 0.00 0 0 0 0 Execute 2 0.00 0.00 0 0 0 0 Fetch 6670 2.06 3.09 47315 46930 0 100010 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 6674 2.06 3.09 47315 46930 0 100010 Misses in library cache during parse: 1 Misses in library cache during execute: 1 Optimizer mode: ALL_ROWS Parsing user id: 31 (TESTUSER) Rows Row Source Operation ------- --------------------------------------------------- 100000 FILTER (cr=24673 pr=26419 pw=5239 time=41377235 us) 100000 HASH JOIN (cr=24673 pr=26419 pw=5239 time=41177148 us) 100000 TABLE ACCESS FULL T1 (cr=11128 pr=11113 pw=0 time=495 us) 100000 TABLE ACCESS FULL T2 (cr=13545 pr=10067 pw=0 time=100493 us) Rows Execution Plan ------- --------------------------------------------------- 0 SELECT STATEMENT MODE: ALL_ROWS 100000 FILTER 100000 HASH JOIN 100000 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID) OF 'T1' (TABLE) 100000 INDEX MODE: ANALYZED (RANGE SCAN) OF 'SYS_C0020592' (INDEX (UNIQUE)) 0 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID) OF 'T2' (TABLE) 0 INDEX MODE: ANALYZED (RANGE SCAN) OF 'SYS_C0020593' (INDEX (UNIQUE))
Hopefully, the above helps you understand why I did not suggest the use of the EXPLAIN parameter.
The calculated cost may be very misleading. There are a large number of factors that are considered when the costs are derived, and some of those factors may mislead the optimizer into either understating the true cost to the end user (typically considered to be execution time) or overstating the true cost to the end user. To the query optimizer, cost is supposed to represent time, but as I stated, you should NOT compare the calculated cost of one query with the calculated cost for another query.
It would probably be beneficial for you to experiment with a couple of things:
- 10046 trace at either level 8 or 12
- SET TIMING ON in SQL*Plus
- DBMS_XPLAN.DISPLAY_CURSOR
Ignore the costs.
For fun, here is another test script, using the same tables that were created earlier:
VARIABLE N1 NUMBER VARIABLE N2 NUMBER EXEC :N1:=1 EXEC :N2:=100000 SET TIMING ON SET AUTOTRACE TRACEONLY STATISTICS EXPLAIN SET PAGESIZE 1000 SET LINESIZE 140 ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12'; ALTER SESSION SET TRACEFILE_IDENTIFIER = 'EXPLAIN_PLAN_TEST2'; SELECT T1.C1, T2.C1, SUBSTR(T1.C2,1,1) T1_C2, SUBSTR(T2.C2,1,1) T2_C2 FROM T1, T2 WHERE T1.C1=T2.C1 AND T1.C1 BETWEEN :N1 AND :N2; EXEC :N2:=10 SELECT T1.C1, T2.C1, SUBSTR(T1.C2,1,1) T1_C2, SUBSTR(T2.C2,1,1) T2_C2 FROM T1, T2 WHERE T1.C1=T2.C1 AND T1.C1 BETWEEN :N1 AND :N2; SELECT SYSDATE FROM DUAL; ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';
I actually executed the script a couple of times, changing the TRACEFILE_IDENTIFIER each time, because the first execution would require a hard parse and would likely require more physical reads – I wanted to factor those out of the run time. The following was displayed when the script ran:
100000 rows selected.
Elapsed: 00:00:03.82
Execution Plan
----------------------------------------------------------
Plan hash value: 77308553
----------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
----------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 749 | 380K| 111 (1)| 00:00:01 |
|* 1 | FILTER | | | | | |
|* 2 | HASH JOIN | | 749 | 380K| 111 (1)| 00:00:01 |
| 3 | TABLE ACCESS BY INDEX ROWID| T1 | 750 | 190K| 55 (0)| 00:00:01 |
|* 4 | INDEX RANGE SCAN | SYS_C0020592 | 1350 | | 4 (0)| 00:00:01 |
| 5 | TABLE ACCESS BY INDEX ROWID| T2 | 750 | 190K| 55 (0)| 00:00:01 |
|* 6 | INDEX RANGE SCAN | SYS_C0020593 | 1350 | | 4 (0)| 00:00:01 |
----------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter(TO_NUMBER(:N1)<=TO_NUMBER(:N2))
2 - access("T1"."C1"="T2"."C1")
4 - access("T1"."C1">=TO_NUMBER(:N1) AND "T1"."C1"<=TO_NUMBER(:N2))
6 - access("T2"."C1">=TO_NUMBER(:N1) AND "T2"."C1"<=TO_NUMBER(:N2))
Statistics
------------------------------------------------
0 recursive calls
0 db block gets
28923 consistent gets
21711 physical reads
0 redo size
2051555 bytes sent via SQL*Net to client
73660 bytes received via SQL*Net from client
6668 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
100000 rows processed
10 rows selected.
Elapsed: 00:00:01.04
Execution Plan
----------------------------------------------------------
Plan hash value: 77308553
----------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
----------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 749 | 380K| 111 (1)| 00:00:01 |
|* 1 | FILTER | | | | | |
|* 2 | HASH JOIN | | 749 | 380K| 111 (1)| 00:00:01 |
| 3 | TABLE ACCESS BY INDEX ROWID| T1 | 750 | 190K| 55 (0)| 00:00:01 |
|* 4 | INDEX RANGE SCAN | SYS_C0020592 | 1350 | | 4 (0)| 00:00:01 |
| 5 | TABLE ACCESS BY INDEX ROWID| T2 | 750 | 190K| 55 (0)| 00:00:01 |
|* 6 | INDEX RANGE SCAN | SYS_C0020593 | 1350 | | 4 (0)| 00:00:01 |
----------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter(TO_NUMBER(:N1)<=TO_NUMBER(:N2))
2 - access("T1"."C1"="T2"."C1")
4 - access("T1"."C1">=TO_NUMBER(:N1) AND "T1"."C1"<=TO_NUMBER(:N2))
6 - access("T2"."C1">=TO_NUMBER(:N1) AND "T2"."C1"<=TO_NUMBER(:N2))
Statistics
---------------------------------------------
0 recursive calls
0 db block gets
22257 consistent gets
21716 physical reads
0 redo size
605 bytes sent via SQL*Net to client
334 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
10 rows processed
In the above, notice that the first execution required 3.82 seconds, and had a calculated cost of 111. The second execution required 1.04 seconds, and also had a calculated cost of 111. Note also that the displayed execution plan is incorrect. The elapsed time was output automatically because the script included SET TIMING ON. Keep in mind the effects of the buffer cache – the first time a SQL statement is executed, it will probably take longer to execute than it does on the second execution, and that is the reason why I executed the SQL statement a couple of extra times before I started looking at the performance. The above statistics indicate that 21,711 physical block reads were performed and 28,923 consistent gets on the first execution. On the second execution the number of physical block reads increased to 21,716 while the number of consistent gets decreased to 22,257.
If we run the 10046 trace file through TKPROF:
TKPROF test_ora_1608_explain_plan_test2.trc test_ora_1608_explain_plan_test2.txt
We now see the following in the resulting output:
SELECT T1.C1, T2.C1, SUBSTR(T1.C2,1,1) T1_C2, SUBSTR(T2.C2,1,1) T2_C2 FROM T1, T2 WHERE T1.C1=T2.C1 AND T1.C1 BETWEEN :N1 AND :N2 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 2 0.00 0.00 0 0 0 0 Execute 2 0.00 0.00 0 0 0 0 Fetch 6670 2.35 2.60 43427 51180 0 100010 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 6674 2.35 2.60 43427 51180 0 100010 Misses in library cache during parse: 0 Optimizer mode: ALL_ROWS Parsing user id: 31 Rows Row Source Operation ------- --------------------------------------------------- 100000 FILTER (cr=28923 pr=21711 pw=0 time=1299979 us) 100000 HASH JOIN (cr=28923 pr=21711 pw=0 time=1199904 us) 100000 TABLE ACCESS FULL T1 (cr=11128 pr=11028 pw=0 time=596 us) 100000 TABLE ACCESS FULL T2 (cr=17795 pr=10683 pw=0 time=100562 us) Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message to client 6670 0.00 0.00 db file scattered read 436 0.01 0.97 db file sequential read 755 0.00 0.05 SQL*Net message from client 6670 0.01 1.86
The wait events are critical to the understanding of why the query required as long as it did to execute.
Now, let’s jump into the 10046 raw trace file. We see the following:
PARSING IN CURSOR #6 len=145 dep=0 uid=31 oct=3 lid=31 tim=3828906982 hv=631402459 ad='a68ddf18' SELECT T1.C1, T2.C1, SUBSTR(T1.C2,1,1) T1_C2, SUBSTR(T2.C2,1,1) T2_C2 FROM T1, T2 WHERE T1.C1=T2.C1 AND T1.C1 BETWEEN :N1 AND :N2 END OF STMT PARSE #6:c=0,e=33,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=3828906975 BINDS #6: kkscoacd Bind#0 oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00 oacflg=03 fl2=1000000 frm=00 csi=00 siz=48 off=0 kxsbbbfp=13cb6528 bln=22 avl=02 flg=05 value=1 Bind#1 oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00 oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=24 kxsbbbfp=13cb6540 bln=22 avl=02 flg=01 value=100000 ... STAT #6 id=1 cnt=100000 pid=0 pos=1 obj=0 op='FILTER (cr=28923 pr=21711 pw=0 time=1299979 us)' STAT #6 id=2 cnt=100000 pid=1 pos=1 obj=0 op='HASH JOIN (cr=28923 pr=21711 pw=0 time=1199904 us)' STAT #6 id=3 cnt=100000 pid=2 pos=1 obj=114319 op='TABLE ACCESS FULL T1 (cr=11128 pr=11028 pw=0 time=596 us)' STAT #6 id=4 cnt=100000 pid=2 pos=2 obj=114321 op='TABLE ACCESS FULL T2 (cr=17795 pr=10683 pw=0 time=100562 us)'
There is the hash value: hv=631402459 (we should probably also do something with the address because of the possibility of multiple unrelated SQL statements potentially having the same hash value). Now, back in SQL*Plus, we can do the following:
SET AUTOTRACE OFF SELECT SQL_ID FROM V$SQL WHERE HASH_VALUE=631402459; SQL_ID ------------- 5pf2mzwku4vyv
There is the SQL_ID that we need to pull the actual execution plan from the library cache. If we integrate that SQL statement into another than pulls back the actual execution plan, this is what we see:
SELECT
*
FROM
TABLE(DBMS_XPLAN.DISPLAY_CURSOR(
(SELECT
SQL_ID
FROM
V$SQL
WHERE
HASH_VALUE=631402459),
NULL,
'TYPICAL +PEEKED_BINDS'));
SQL_ID 5pf2mzwku4vyv, child number 0
-------------------------------------
SELECT T1.C1, T2.C1, SUBSTR(T1.C2,1,1) T1_C2, SUBSTR(T2.C2,1,1)
T2_C2 FROM T1, T2 WHERE T1.C1=T2.C1 AND T1.C1 BETWEEN :N1 AND :N2
Plan hash value: 487071653
------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes |TempSpc| Cost (%CPU)| Time |
------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | | 1809 (100)| |
|* 1 | FILTER | | | | | | |
|* 2 | HASH JOIN | | 100K| 49M| 25M| 1809 (4)| 00:00:09 |
|* 3 | TABLE ACCESS FULL| T1 | 100K| 24M| | 568 (5)| 00:00:03 |
|* 4 | TABLE ACCESS FULL| T2 | 100K| 24M| | 568 (5)| 00:00:03 |
------------------------------------------------------------------------------------
Peeked Binds (identified by position):
--------------------------------------
1 - :N1 (NUMBER): 1
2 - :N2 (NUMBER): 100000
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter(:N1<=:N2)
2 - access("T1"."C1"="T2"."C1")
3 - filter(("T1"."C1"<=:N2 AND "T1"."C1">=:N1))
4 - filter(("T2"."C1"<=:N2 AND "T2"."C1">=:N1))
So, the above shows the calculated cost (1809) for the actual execution plan used for the query when it was executed and the peeked bind variables that were submitted during the hard parse.
The next example changes the STATISTICS_LEVEL at the session level to ALL, which has a tendency to increase the execution time for queries (a hint can be added to the query so that changing the STATISTICS_LEVEL is not necessary):
VARIABLE N1 NUMBER VARIABLE N2 NUMBER EXEC :N1:=1 EXEC :N2:=100000 ALTER SESSION SET STATISTICS_LEVEL='ALL'; SELECT T1.C1, T2.C1, SUBSTR(T1.C2,1,1) T1_C2, SUBSTR(T2.C2,1,1) T2_C2 FROM T1, T2 WHERE T1.C1=T2.C1 AND T1.C1 BETWEEN :N1 AND :N2;
OK, let’s see the execution plan for the query that was just executed:
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +PEEKED_BINDS +PROJECTION +ALIAS +PREDICATE +COST +BYTES')); Plan hash value: 487071653 ------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Starts | E-Rows |E-Bytes|E-Temp | Cost (%CPU)| A-Rows | A-Time | Buffers | Reads | Writes | OMem| 1Mem | Used-Mem | Used-Tmp| ------------------------------------------------------------------------------------------------------------------------------------------------------------------------- |* 1 | FILTER | | 1 | | | | | 100K|00:00:04.56 | 23056 | 27980 | 6231 | | | | | |* 2 | HASH JOIN | | 1 | 100K| 49M| 25M| 1809 (4)| 100K|00:00:04.45 | 23056 | 27980 | 6231 | 29M| 3792K| 11M (1)| 52224 | |* 3 | TABLE ACCESS FULL| T1 | 1 | 100K| 24M| | 568 (5)| 100K|00:00:01.99 | 11128 | 11054 | 0 | | | | | |* 4 | TABLE ACCESS FULL| T2 | 1 | 100K| 24M| | 568 (5)| 100K|00:00:01.51 | 11928 | 10695 | 0 | | | | | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------- Query Block Name / Object Alias (identified by operation id): ------------------------------------------------------------- 1 - SEL$1 3 - SEL$1 / T1@SEL$1 4 - SEL$1 / T2@SEL$1 Peeked Binds (identified by position): -------------------------------------- 1 - (NUMBER): 1 2 - (NUMBER): 100000 Predicate Information (identified by operation id): --------------------------------------------------- 1 - filter(:N1<=:N2) 2 - access("T1"."C1"="T2"."C1") 3 - filter(("T1"."C1"<=:N2 AND "T1"."C1">=:N1)) 4 - filter(("T2"."C1"<=:N2 AND "T2"."C1">=:N1)) Column Projection Information (identified by operation id): ----------------------------------------------------------- 1 - "T1"."C1"[NUMBER,22], "T2"."C1"[NUMBER,22], "T1"."C2"[VARCHAR2,255], "T2"."C2"[VARCHAR2,255] 2 - (#keys=1) "T1"."C1"[NUMBER,22], "T2"."C1"[NUMBER,22], "T1"."C2"[VARCHAR2,255], "T2"."C2"[VARCHAR2,255] 3 - "T1"."C1"[NUMBER,22], "T1"."C2"[VARCHAR2,255] 4 - "T2"."C1"[NUMBER,22], "T2"."C2"[VARCHAR2,255]
The above shows the estimated costs as well as the actual execution statistics.
This blog has a number of related articles. For example, this one on DBMS_XPLAN.
Charles Hooper's Oracle Notes 
Recent Comments