Re: 'alter session set sql_trace=true' bug or feature ?

From: Niall Litchfield <n-litchfield_at_audit-commission.gov.uk>
Date: Tue, 23 Dec 2003 09:48:01 -0000
Message-ID: <3fe80f52$0$9393$ed9e5944@reading.news.pipex.net>

"VC" <boston103_at_hotmail.com> wrote in message news:xtLFb.625746$Tr4.1620004_at_attbi_s03...
> Hello dx,
>
> Please see below:
> "dx" <seaelephant_at_hotmail.com> wrote in message
> news:7f28ac37.0312221301.664a36e2_at_posting.google.com...
> > sql*plus set timing is broken some time, you'd better not use it to
> > time sql running, set autotrace on also introduce overhead.
> >
>
> Firstly, I must apologize for my forgetting to mention that Oracle
> 9..2.0.1does not exhibit this kind of behaviour. I did mention in my
> original message that I was using was 9.2.0.4.
>
>
> >>"dx" Here are two scripts I used to test.
>
> Secondly, just for the fun of it, I ran your scripts, slightly modified
to
> avoid sqlplus influence entirely. Here are the results:
<snip test>

I think that this is an excellent test. I modified it slightly to use event 10046 as show below

<snip setup of table which is the same as for you>

spool c:\oracle\logresults\query1.txt

alter session set events '10046 trace name context forever, level 8';

declare
l_start number;
begin
l_start := dbms_utility.get_time;
for l_record in
(select a.id, count(*)
from
(select id from t1) a
join
(select id from t1) b
on a.id<=b.id group by a.id) loop
null;
end loop;
dbms_output.put_line( (dbms_utility.get_time - l_start)/100 ||'seconds....' );
end;
/

prompt set tracing off

alter session set events '10046 trace name context off';

declare
l_start number;
begin
l_start := dbms_utility.get_time;
for l_record in
(select a.id, count(*)
from
(select id from t1) a
join
(select id from t1) b
on a.id<=b.id group by a.id) loop
null;
end loop;
dbms_output.put_line( (dbms_utility.get_time - l_start)/100 ||'seconds....' );
end;
/

spool off

spool c:\oracle\logresults\query2.txt

alter session set events '10046 trace name context forever, level 8'

declare
l_start number;
begin
l_start := dbms_utility.get_time;
for l_record in (select sysdate from all_objects) loop

null;
end loop;
dbms_output.put_line( (dbms_utility.get_time - l_start)/100 ||'seconds....' );
end;
/

alter session set events '10046 trace name context off';

declare
l_start number;
begin
l_start := dbms_utility.get_time;
for l_record in (select sysdate from all_objects) loop

null;
end loop;
dbms_output.put_line( (dbms_utility.get_time - l_start)/100 ||'seconds....' );
end;
/

spool off

and get the following results

query1

---

Session altered.

2.94seconds....

PL/SQL procedure successfully completed.

set tracing off

Session altered.

.29seconds....

PL/SQL procedure successfully completed.

i.e comparable to you.

query2

---

1.17seconds....

PL/SQL procedure successfully completed.

Session altered.

1.17seconds....

PL/SQL procedure successfully completed.

SQL> spool off

i.e no measurable difference

> Lastly, I would not call this kind of behaviour 'overhead'. Would'nt you
> agree that the tool, in its present state, is practically useless for
> performance tuning ?

So I think that I disagree with your statement. Where the impact is significant then the tool is unhelpful, however where the overhead is insignificant then it isn't.

This raises the question 'How do I know if the impact is significant?' to which I guess the only answer is to compare elapsed times with and without tracing, you ought if you are concentrating on problem processes to get a good idea of this early on as you should IMO always compare the elapsed times in your traced sessions to those experienced by the end users, if nothing else to make sure you are tracing the right thing.

Having said all that some further digging on metalink suggests that there is a bug 3009359 which has been filed against this issue against a forum thread you raised in June. Have you tried pushing Oracle for a status update on this bug?

-- 
Niall Litchfield
Oracle DBA
Audit Commission UK

Received on Tue Dec 23 2003 - 03:48:01 CST