Home » RDBMS Server » Performance Tuning » Execution Plan in Trace File
Execution Plan in Trace File [message #223121] Wed, 07 March 2007 12:02 Go to next message
scottwmackey
Messages: 505
Registered: March 2005
Senior Member
Does anybody know why the execution plan used by a query shows up only intermittently in TKPROF files. And with all due respect to anybody who is tempted to respond that I need to use the "explain" parameter when running TKPROF, that is not what I am talking about. I know the "explain" parameter will give me an execution plan, even though it may not actually have been used when the query was run. Tom Kyte implies in more than one place that there should be an execution plan in every TKPROF file, and sometimes I see one. I am just wondering why it is not always there. Does anybody know, or more importantly, does anybody know what I need to do to always get one?
Re: Execution Plan in Trace File [message #223122 is a reply to message #223121] Wed, 07 March 2007 12:06 Go to previous messageGo to next message
BlackSwan
Messages: 25046
Registered: January 2009
Location: SoCal
Senior Member
I always enable SQL_TRACE with LEVEL=12 & always get EXPLAIN_PLAN.

HTH & YMMV
Re: Execution Plan in Trace File [message #223145 is a reply to message #223121] Wed, 07 March 2007 13:53 Go to previous messageGo to next message
gintsp
Messages: 118
Registered: February 2007
Senior Member
Stats are written only after the cursor is closed
http://asktom.oracle.com/pls/asktom/f?p=100:11:0::::P11_QUESTION_ID:6904032233295

So either disconnect or probably you can get along with some dummy select 'blahh' from dual;

Another possibility might be that your trace file is simply truncated.

Gints Plivna
http://www.gplivna.eu
Re: Execution Plan in Trace File [message #223217 is a reply to message #223145] Thu, 08 March 2007 00:47 Go to previous messageGo to next message
rleishman
Messages: 3724
Registered: October 2005
Location: Melbourne, Australia
Senior Member
I concur with @gintsp. I have seen both happen a lot.

Although I have had situations where the cursor is closed, the plan steps are in the trace file, but TK*Prof does not show them. I didn't stress about it at the time because I could get the info I needed straight from the trace file.

Ross Leishman

Re: Execution Plan in Trace File [message #223229 is a reply to message #223121] Thu, 08 March 2007 01:40 Go to previous messageGo to next message
scottwmackey
Messages: 505
Registered: March 2005
Senior Member
Thanks to all of you, especially gintsp. There appears to be one more thing that I failed to mention which seems to make a big difference. The sql statement was part of an insert, e.g.
INSERT INTO t VALUES(...)
SELECT ...
FROM t
     ...
WHERE ...
This is apparently treated differently than if the select statement is like this
SELECT ...
BULK COLLECT INTO ...
FROM t
     ...
WHERE ...
It would appear I fell victim to my own admonition I give to newbies. Don't omit anything in your description of the problem. You don't know what is and isn't relevant.

Nevertheless, I found the following. If I
ALTER SESSION SET SQL_TRACE = TRUE;

BEGIN
    my_proc; --(with insert/select)
END;

(Switch to udump) TKPROF ...
I don't get the execution plan. If I just close the window (I am working through multi-session enabled PL/SQL Developer) on which I am working, which ends the session, and then run TKPROF, I get the execution plan. So gintsp, that's where your observation was spot on. When I do this one
ALTER SESSION SET SQL_TRACE = TRUE;

BEGIN
    my_proc; --(with select into bulk collect)
END;

(Switch to udump) TKPROF ...
I get the execution plan without having to close the window or even turn off trace. That seems kind of strange but I can live with it.
Re: Execution Plan in Trace File [message #223436 is a reply to message #223229] Thu, 08 March 2007 22:07 Go to previous message
rleishman
Messages: 3724
Registered: October 2005
Location: Melbourne, Australia
Senior Member
On a similar but completely unrelated topic, I managed to break TK*Prof today. Have a look at what it gave me:

SELECT /*+ordered use_nl(m)*/ *
FROM   orders o
,      delivery_method m
WHERE  o.order_amt BETWEEN m.lower_bound and m.upper_bound
AND    m.upper_bound =  (
       SELECT min(m1.upper_bound)
       FROM   delivery_method m1
       WHERE  m1.upper_bound >= o.order_amt
)

call     count       cpu    elapsed       disk      query
------- ------  -------- ---------- ---------- ----------
Parse        1      0.01       0.00          0          0
Execute      1      0.00       0.00          0          0
Fetch      603      0.42       0.77         78      50936
------- ------  -------- ---------- ---------- ----------
total      605      0.43       0.77         78      50936

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 33

Rows     Row Source Operation
-------  ---------------------------------------------------
   9021  TABLE ACCESS BY INDEX ROWID DELIVERY_METHOD
  20001   NESTED LOOPS
  10000    TABLE ACCESS FULL ORDERS
  10000    INDEX RANGE SCAN DELIVERY_METHOD_PK


There are 3 lines missing from the bottom of the plan. I checked the trace file, they're not in there either. The trace file was not tuncated, there were hundreds of following lines from other SQLs that I ran. Only this statement was truncated...?

I dopped and rebuilt the DELIVERY_METHOD table, but this time with fewer rows. Run it again and get:

SELECT /*+ordered use_nl(m)*/ *
FROM   orders o
,      delivery_method m
WHERE  o.order_amt BETWEEN m.lower_bound and m.upper_bound
AND    m.upper_bound =  (
       SELECT min(m1.upper_bound)
       FROM   delivery_method m1
       WHERE  m1.upper_bound >= o.order_amt
)

call     count       cpu    elapsed       disk      query
------- ------  -------- ---------- ---------- ----------
Parse        1      0.00       0.00          0          0
Execute      1      0.00       0.00          0          0
Fetch       34      0.23       0.41         42      30597
------- ------  -------- ---------- ---------- ----------
total       36      0.23       0.41         42      30597

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 33

Rows     Row Source Operation
-------  ---------------------------------------------------
    491  FILTER
    491   NESTED LOOPS
  10000    TABLE ACCESS FULL ORDERS
    491    TABLE ACCESS FULL DELIVERY_METHOD
    491   SORT AGGREGATE
    491    FIRST ROW
    491     INDEX RANGE SCAN (MIN/MAX) DELIVERY_METHOD_PK


The plan is complete this time!!! Drop and rebuild the table again back to its bigger size - bad plan again.

I'm not asking for assistance here, just pointing out that SQL Trace is not always God-like and predictable.

Ross Leishman

Previous Topic: Reverse Key Index
Next Topic: Poor Performance query
Goto Forum:
  


Current Time: Wed Dec 07 10:54:13 CST 2016

Total time taken to generate the page: 0.11357 seconds