| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
 |
 | |||
| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
|
| |||
Home -> Community -> Usenet -> c.d.o.server -> Re: newbie, getting cost plan
On Sep 8, 3:31 am, codefragm..._at_googlemail.com wrote:
> On 7 Sep, 16:45, Charles Hooper <hooperc2..._at_yahoo.com> wrote:
>
> > On Sep 7, 7:43 am, sybrandb <sybra..._at_gmail.com> wrote:
>
> > > On Sep 7, 1:07 pm, codefragm..._at_googlemail.com wrote:
>
> > > > Hi
> > > > I want to get the -real- cost and plan of an sql statement, not
> > > > estimated I can use:
>
> > > > (1) Explain Plan and DBMS_XPLAN from sqlplus, I gather this isn't the
> > > > real plan?
> > > > (2) Autotrace On, I gather this will be the real plan?
> > > > (3) tracing and tkprof, which can use explain plan, is this the real
> > > > plan?
>
> > > > and there are other ways I've seen mentioned?
> > > > In my present scenario I can do what I want with the database and
> > > > application.
>
> > > > thanks
>
> > > tracing and tkprof is the easiest, provided you do NOT use the
> > > explain= option (as this will run a new explain plan) and you left
> > > sql*plus properly before running tkprof (ie you issued a COMMIT or
> > > ROLLBACK which will have Oracle dump the real explain plan)
>
> > > Other than that you could of course run statspack on level 6. This
> > > will save the real explain plan, in the statspack tables. Doing so,
> > > you can use sprepsql to retrieve the explain plan. Note: the method to
> > > do so is user unfrienly, however it works.
>
> > > --
> > > Sybrand Bakker
> > > Senior Oracle DBA
>
> > I have effectively used the TKPROF method mentioned by Sybrand. Once
> > you have an understanding of how to read the STAT lines in the raw
> > trace files (see Cary Millsap's book), you can even skip the use of
> > TKPROF - as long as multiple cursors are not opened simultaneously it
> > is easy to keep things straight.
> > Cost -> Time in the actual plan.
>
> > To set up for this, modify the original SQL statement with a hint like
> > this:
> > SELECT /*+ GATHER_PLAN_STATISTICS */
> > MIN(SYSDATE)
> > FROM
> > ALL_TABLES;
>
> > Execute the SQL statement, and then to retrieve the actual execution
> > statistics:
> > SELECT
> > *
> > FROM
> > TABLE (DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));
>
> > If instead you wanted the estimated statistics:
> > SELECT
> > *
> > FROM
> > TABLE (DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,NULL));
>
> > More information can be found here:http://jonathanlewis.wordpress.com/2006/11/09/dbms_xplan-in-10g/
>
> > Charles Hooper
> > IT Manager/Oracle DBA
> > K&M Machine-Fabricating, Inc.
>
> Oracle version 9 for me (and in some cases 8!)
>
> Sorry, I didn't mention it as I'm from a Microsoft SQL background and
> didn't think this
> would be a new thing but something thats been there for a large number
> of years.
No problem, we will just use the method suggested by Sybrand. Let's
assume that you can execute the SQL statement in question in SQL*Plus,
or some other query tool. Before you execute the SQL statement,
execute the following:
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';
The above turns on a 10046 trace at level 8, meaning the Oracle will
not only retrieve the execution plan, but will also indicate what
causes the delays. Once the above is executed, execute your SQL
statement. The following is a trace from Oracle 8.1.7.3 (you will
likely find yours in the udump directory), my comments are in {}:
PARSING IN CURSOR #1 len=799 dep=0 uid=22 oct=3 lid=22 tim=250719498
hv=1165133217 ad='7ac4abc'
{dep=0 indicates SQL statement was executed in an application, dep=1,
dep=2, etc. indicates trigger or space management code executed
automatically in response to the SQL statement executed in the
application. uid=Schema user ID of the user who parsed the SQL
statement. oct=Oracle command type. hv=Statement ID of the SQL
statement, may not be a unique number - can be used with the various V
$SQL_ views}
SELECT
CO.CUSTOMER_ID,
CO.CUSTOMER_PO_REF,
COL.CUST_ORDER_ID||:"SYS_B_0"||COL.LINE_NO AS CUST_ORDER,
COL.PART_ID,
P.DESCRIPTION,
P.WEIGHT,
COL.DESIRED_SHIP_DATE,
COL.TOTAL_SHIPPED_QTY||:"SYS_B_1"||COL.ORDER_QTY AS QTY_SHIPPED,
(COL.ORDER_QTY-COL.TOTAL_SHIPPED_QTY) AS QTY_NEEDED,
COL.UNIT_PRICE AS PRICE,
P.QTY_ON_HAND,
QAP.QTY QAP_QTY
FROM
CUST_ORDER_LINE COL,
CUSTOMER_ORDER CO,
PART P,
QS_AVAILABLE_PARTS QAP
WHERE COL.DESIRED_SHIP_DATE Between :"SYS_B_2" AND :"SYS_B_3"
AND COL.ORDER_QTY > COL.TOTAL_SHIPPED_QTY
AND COL.CUST_ORDER_ID=CO.ID
AND CO.CUSTOMER_ID <> :"SYS_B_4"
AND CO.STATUS <> :"SYS_B_5"
AND COL.PART_ID=P.ID
AND COL.PART_ID=QAP.PART_ID(+)
ORDER BY
CO.CUSTOMER_ID,
COL.CUST_ORDER_ID,
COL.LINE_NO
{Note the :"SYS_B_0", :"SYS_B_1", etc. in the SQL statement - I had
CURSOR_SHARING set to true when I passed in constants, and Oracle
automatically replaced the constants with bind variables}
END OF STMT
PARSE #1:c=2,e=2,p=0,cr=2,cu=0,mis=1,r=0,dep=0,og=0,tim=250719500
{On 8i, c= and e= are specified in 1/100th of a second, on 9i and
above these are specified in 1/1,000,000th of a second - it took 0.02
seconds of CPU time to parse the SQL statement, the elapsed (wall
clock, actual) time was also 0.02 seconds. There were no physical
blocks read from disk (p), but there were 2 blocks read in consistent
read mode (cr), and 0 blocks read in current mode (cu). This SQL
statement was not found in the shared pool (mis=1), and Oracle's
optimizer goal was choose (?) (1=ALL_ROWS, 2=FIRST_ROWS, 3=RULE,
4=CHOOSE)}
EXEC #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=250719500
{Not much new information presented here when the SQL statement was
executed, although we now see that the optimizer goal was choose.}
WAIT #1: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1
p3=0
FETCH
#1:c=17,e=17,p=0,cr=2557,cu=23,mis=0,r=10,dep=0,og=4,tim=250719517
{The initial fetch requires 0.17 seconds of CPU time, the elapsed time
is also 0.17 seconds, no blocks were read from disk, 2557 blocks were
read from the buffer cache in consistent read mode, 23 blocks were
read from the buffer cache in current mode (faster than consistent
read), the client retrieved 10 rows, and you may also note that the
tim= value increased by 17.}
XCTEND rlbk=0, rd_only=1
{The client commits, but does not change anything}
WAIT #1: nam='SQL*Net more data to client' ela= 0 p1=1413697536
p2=2062 p3=0
WAIT #1: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1
p3=0
WAIT #1: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1
p3=0
{Data is sent to the client, and the client requests additional data}
FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=11,dep=0,og=4,tim=250719517
{11 rows are retrieved for the client}
WAIT #1: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1
p3=0
WAIT #1: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1
p3=0
FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=11,dep=0,og=4,tim=250719517
WAIT #1: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1
p3=0
WAIT #1: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1
p3=0
FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=11,dep=0,og=4,tim=250719517
WAIT #1: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1
p3=0
WAIT #1: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1
p3=0
FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=11,dep=0,og=4,tim=250719517
WAIT #1: nam='SQL*Net message from client' ela= 1 p1=1413697536 p2=1
p3=0
WAIT #1: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1
p3=0
FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=11,dep=0,og=4,tim=250719518
WAIT #1: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1
p3=0
WAIT #1: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1
p3=0
FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=11,dep=0,og=4,tim=250719518
WAIT #1: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1
p3=0
WAIT #1: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1
p3=0
FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=6,dep=0,og=4,tim=250719520
WAIT #1: nam='SQL*Net message from client' ela= 1 p1=1413697536 p2=1
p3=0
STAT #1 id=1 cnt=192 pid=0 pos=0 obj=0 op='SORT ORDER BY ' STAT #1 id=2 cnt=192 pid=1 pos=1 obj=0 op='NESTED LOOPS ' STAT #1 id=3 cnt=193 pid=2 pos=1 obj=0 op='HASH JOIN OUTER ' STAT #1 id=4 cnt=192 pid=3 pos=1 obj=0 op='HASH JOIN ' STAT #1 id=5 cnt=192 pid=4 pos=1 obj=3380 op='TABLE ACCESS FULLCUST_ORDER_LINE '
STAT #1 id=7 cnt=590 pid=3 pos=2 obj=0 op='VIEW QS_AVAILABLE_PARTS ' STAT #1 id=8 cnt=590 pid=7 pos=1 obj=0 op='SORT GROUP BY ' STAT #1 id=9 cnt=73926 pid=8 pos=1 obj=4446 op='TABLE ACCESS FULLQUALITY_SCAN '
id=1 cnt=192 SORT ORDER BY id=2 cnt=192 NESTED LOOPS id=3 cnt=193 HASH JOIN OUTER id=4 cnt=192 HASH JOIN id=5 cnt=192 TABLE ACCESS FULL CUST_ORDER_LINE id=6 cnt=5250 TABLE ACCESS FULL CUSTOMER_ORDER id=7 cnt=590 VIEW QS_AVAILABLE_PARTS id=8 cnt=590 SORT GROUP BY id=9 cnt=73926 TABLE ACCESS FULL QUALITY_SCAN id=10 cnt=192 TABLE ACCESS BY INDEX ROWID PART id=11 cnt=384 INDEX UNIQUE SCAN (look up obj=36798 to find theindex name)
You could of course just send the trace file into TKPROF once it is
available either on the local drive or a mapped drive. From a command
line:
c:\> TKPROF C:\SourceTraceFile.trc C:\Output.txt sort=EXEELA
However, be aware that this dilutes the information in the trace file,
and may be a bit misleading. An example output (using a different
trace file as the source):
select NVL(sum(order_qty - total_shipped_qty), 0)
from CUST_ORDER_LINE l, CUSTOMER_ORDER o
where part_id = :1
and l.cust_order_id = o.id
and ((l.desired_ship_date is not null and l.desired_ship_date <= :
2 )
or (l.desired_ship_date is null and o.desired_ship_date <= :
3 ))
and o.status in ('F', 'R')
and order_qty > total_shipped_qty
call count cpu elapsed disk query current rows
Parse 2412 6.28 6.75 0 0 0 0 Execute 2412 0.38 0.42 0 0 0 0 Fetch 2412 0.87 1.41 62 4864 0 2412
total 7236 7.53 8.58 62 4864 0 2412
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer goal: CHOOSE
Parsing user id: 78
Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE
0 NESTED LOOPS
1 TABLE ACCESS BY INDEX ROWID CUST_ORDER_LINE
1 INDEX RANGE SCAN (object id 4602)
0 TABLE ACCESS BY INDEX ROWID CUSTOMER_ORDER
0 INDEX UNIQUE SCAN (object id 36784)
Note that you can also activate a trace for another session, from
SQL*Plus, after retrieving the SID and SERIAL# of the session to be
traced from V$SESSION:
EXEC SYS.DBMS_SYSTEM.SET_EV(sid,serial#,10046,8)
Charles Hooper
IT Manager/Oracle DBA
K&M Machine-Fabricating, Inc.
Received on Sat Sep 08 2007 - 08:06:23 CDT
 |
 |