Why does the statistics report in the explain plan take more time to be
generated?

When I use "set autotrace traceonly explain", it takes zero seconds for
the plan to be generated. If the autotrace is set to "set autotrace
traceonly explain statistics" then it takes 14 seconds. Any idea why
this happens?


SQL> desc test_p
Name Null? Type
----------------------------------------- -------- -----------------
MYCOL1 NUMBER

SQL> truncate table test_p;

Table truncated.

Elapsed: 00:00:00.00
SQL> set autotrace traceonly explain
SQL> select * from test_p;
Elapsed: 00:00:00.00

Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE
1 0 TABLE ACCESS (FULL) OF 'TEST_P'



SQL> set autotrace traceonly explain statistics
SQL> /

no rows selected

Elapsed: 00:00:14.04

Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE
1 0 TABLE ACCESS (FULL) OF 'TEST_P'




Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
3 consistent gets
0 physical reads
0 redo size
140 bytes sent via SQL*Net to client
232 bytes received via SQL*Net from client
1 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
0 rows processed

Prasath wrote:

If you would think one sec about it, you would realize those statistics
need to be SELECTed from your session statistics. Obviously this takes
time.

--
Sybrand Bakker
Senior Oracle DBA

I agree that there might be a slight overhead in collecting the
statisitcs of a query. But I am concerned with the amount of time
taken. There must be something wrong with the session. I am looking
for some clues.

Prasath wrote:
Oracle docs are your friend
http://download-east.oracle.com/docs...3/autotrac.htm

SET AUTOTRACE ON EXPLAIN
The AUTOTRACE report shows only the optimizer execution path.

Only plan, no actual execute of query, therefore such a difference.

Gints Plivna
http://www.gplivna.eu/

"Gints Plivna" <gints.plivna (AT) gmail (DOT) com> a écrit dans le message de news: 1153137348.573607.108590 (AT) m79g20...oglegroups.com...
Wrong! There is no result output but the query is executed.

Regards
Michel Cadot

Michel Cadot wrote:
Hmmmmmm, are you absolutely sure?
10046 level trace shows following lines in trace file for my select
with autotrace traceonly explain:
PARSING IN CURSOR #23 len=24 dep=0 uid=58 oct=3 lid=58 tim=131957562505
hv=104009821 ad='6cee7618'
select count(*) from big
END OF STMT
PARSE
#23:c=0,e=9979,p=0,cr=23,cu=0,mis=1,r=0,dep=0,og=1 ,tim=131957562496
WAIT #23: nam='SQL*Net message to client' ela= 7 driver id=1111838976
#bytes=1 p3=0 obj#=348 tim=131957562643
WAIT #23: nam='SQL*Net message from client' ela= 247 driver
id=1111838976 #bytes=1 p3=0 obj#=348 tim=131957562983

And tkprof shows following output:
select count(*)
from
big


call count cpu elapsed disk query current
rows
------- ------ -------- ---------- ---------- ---------- ----------
----------
Parse 1 0.00 0.00 0 0 0
0
Execute 0 0.00 0.00 0 0 0
0
Fetch 0 0.00 0.00 0 0 0
0
------- ------ -------- ---------- ---------- ---------- ----------
----------
total 1 0.00 0.00 0 0 0
0

So it isn't executed, no rows fetched just parsed.

Of course inserts, deletes and updates are both parsed and executed:
lines from trace file
PARSING IN CURSOR #29 len=38 dep=0 uid=58 oct=2 lid=58 tim=132486678502
hv=3665109320 ad='69bd9bcc'
insert into big values (1, 1, 1, 1, 1)
END OF STMT
PARSE
#29:c=78125,e=92231,p=0,cr=4,cu=0,mis=1,r=0,dep=0, og=1,tim=132486678492
BINDS #29:
WAIT #29: nam='db file sequential read' ela= 10293 file#=4 block#=54025
blocks=1 obj#=50039 tim=132486701502
EXEC
#29:c=0,e=14805,p=1,cr=1,cu=3,mis=0,r=1,dep=0,og=1 ,tim=132486703768

Gints Plivna
http://www.gplivna.eu/

"Gints Plivna" <gints.plivna (AT) gmail (DOT) com> a écrit dans le message de news: 1153165664.992848.207430 (AT) m73g20...oglegroups.com...
Michel Cadot wrote:
Hmmmmmm, are you absolutely sure?
10046 level trace shows following lines in trace file for my select
with autotrace traceonly explain:
PARSING IN CURSOR #23 len=24 dep=0 uid=58 oct=3 lid=58 tim=131957562505
hv=104009821 ad='6cee7618'
select count(*) from big
END OF STMT
PARSE
#23:c=0,e=9979,p=0,cr=23,cu=0,mis=1,r=0,dep=0,og=1 ,tim=131957562496
WAIT #23: nam='SQL*Net message to client' ela= 7 driver id=1111838976
#bytes=1 p3=0 obj#=348 tim=131957562643
WAIT #23: nam='SQL*Net message from client' ela= 247 driver
id=1111838976 #bytes=1 p3=0 obj#=348 tim=131957562983

And tkprof shows following output:
select count(*)
from
big


call count cpu elapsed disk query current
rows
------- ------ -------- ---------- ---------- ---------- ----------
----------
Parse 1 0.00 0.00 0 0 0
0
Execute 0 0.00 0.00 0 0 0
0
Fetch 0 0.00 0.00 0 0 0
0
------- ------ -------- ---------- ---------- ---------- ----------
----------
total 1 0.00 0.00 0 0 0
0

So it isn't executed, no rows fetched just parsed.

Of course inserts, deletes and updates are both parsed and executed:
lines from trace file
PARSING IN CURSOR #29 len=38 dep=0 uid=58 oct=2 lid=58 tim=132486678502
hv=3665109320 ad='69bd9bcc'
insert into big values (1, 1, 1, 1, 1)
END OF STMT
PARSE
#29:c=78125,e=92231,p=0,cr=4,cu=0,mis=1,r=0,dep=0, og=1,tim=132486678492
BINDS #29:
WAIT #29: nam='db file sequential read' ela= 10293 file#=4 block#=54025
blocks=1 obj#=50039 tim=132486701502
EXEC
#29:c=0,e=14805,p=1,cr=1,cu=3,mis=0,r=1,dep=0,og=1 ,tim=132486703768

Gints Plivna
http://www.gplivna.eu/


I think you meant
SET AUTOTRACE TRACEONLY EXPLAIN
and not
SET AUTOTRACE ON EXPLAIN
as you posted.

Regards
Michel Cadot

Oh yea, of course, mea culpa

Gints Plivna
http://www.gplivna.eu/