10046 event is useless in 9.2.0.4 version for response time measuring !!!

From: <J.Velikanovs_at_alise.lv>
Date: Mon, 2 Aug 2004 16:18:42 +0300
Message-ID: <OFDDFD11B0.B856E175-ONC2256EE4.0048E8A8-C2256EE4.0049DF3B@alise.lv>

My regards to all,
At the moment I have impression that, 10046 event is useless in 9.2.0.4 version for response time measuring!
I have tied to run loop.sql (see below for full text) with and without 10046 event on 9.2.0.4 & 9.2.0.5.
The results scared me.
Take a look:
.
9.2.0.4
without 6,45 sec
!!!!!!!!!!! with 37,36 sec
.
9.2.0.5
without 5,48 sec
!!!!!!!!!!! with 7,19 sec
.
After short investigation it is appears that it is BUG 3009359. http://metalink.oracle.com/metalink/plsql/showdoc?db=NOT&id=3009359.8 No one-off fix on 9.2.0.4.
.
So it’s appears, that 10046 is useless on 9.2.0.4, because SQL Trace itself takes 580% of response time.
.
Any comments?!
Have any body solution for this issue.
.
As appears from dictation from this list, to go to 9.2.0.5 is not good idea, because of instability and other issues.

Thanks in advance,
Jurijs

---

• loop.sql declare vn number; begin for f in 1..1000 loop select count(v) into vn from testlio where n between 10000 and 20000; end loop; end; /

  ---

TKPROF output

---

9204

---

SELECT count(v)
from
 testlio where n between 10000 and 20000

call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ----------

---

Parse        1      0.00       0.00          0          0          0     0
Execute   1000      0.08       0.08          0          0          0     0
Fetch     1000     37.07      36.19          0     132000          0  1000

------- ------ -------- ---------- ---------- ---------- ----------

---

total 2001 37.15 36.27 0 132000 0 1000

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: SYS (recursive depth: 1)

Rows Row Source Operation

-------  ---------------------------------------------------

   1000 SORT AGGREGATE (cr=132000 r=0 w=0 time=36185613 us) 10001000 TABLE ACCESS BY INDEX ROWID TESTLIO (cr=132000 r=0 w=0 time=28015044 us)
10001000 INDEX RANGE SCAN TESTLIO_I1 (cr=25000 r=0 w=0 time=9976625 us)(object id 6318)

---

9205

---

SELECT COUNT(V)
FROM
 TESTLIO WHERE N BETWEEN 10000 AND 20000 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ----------

---

Parse        1      0.00       0.00          0          0          0     0
Execute   1000      0.05       0.07          0          0          0     0
Fetch     1000      6.89       6.72          0     132000          0  1000

------- ------ -------- ---------- ---------- ---------- ----------

---

total 2001 6.94 6.81 0 132000 0 1000

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: SYS (recursive depth: 1)

Rows Row Source Operation

-------  ---------------------------------------------------

   1000 SORT AGGREGATE
10001000 TABLE ACCESS BY INDEX ROWID TESTLIO 10001000 INDEX RANGE SCAN TESTLIO_I1 (object id 6289)

---

RAW portion of TRC file

---

9204

---

PARSING IN CURSOR #5 len=60 dep=1 uid=0 oct=3 lid=0 tim=1065854307286108 hv=518780277 ad='5aca2538'
SELECT count(v) from testlio where n between 10000 and 20000 END OF STMT
PARSE #5:c=0,e=485,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,tim=1065854307286097 BINDS #5:
EXEC #5:c=0,e=134,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1065854307286405 FETCH
#5:c=40000,e=36240,p=0,cr=132,cu=0,mis=0,r=1,dep=1,og=4,tim=1065854307322684 BINDS #5:
EXEC #5:c=0,e=85,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1065854307322899 FETCH
#5:c=40000,e=36128,p=0,cr=132,cu=0,mis=0,r=1,dep=1,og=4,tim=1065854307359065 BINDS #5:
EXEC #5:c=0,e=81,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1065854307359268 FETCH
#5:c=30000,e=36181,p=0,cr=132,cu=0,mis=0,r=1,dep=1,og=4,tim=1065854307395487 BINDS #5:
EXEC #5:c=0,e=81,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1065854307395689 FETCH
#5:c=40000,e=36145,p=0,cr=132,cu=0,mis=0,r=1,dep=1,og=4,tim=1065854307431871 BINDS #5:

---

9204

---

PARSING IN CURSOR #5 len=60 dep=1 uid=0 oct=3 lid=0 tim=1065854501680779 hv=4259315813 ad='5bc9bfdc'
SELECT COUNT(V) FROM TESTLIO WHERE N BETWEEN 10000 AND 20000 END OF STMT
PARSE
#5:c=0,e=7476,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,tim=1065854501680769 BINDS #5:
EXEC #5:c=0,e=134,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1065854501681077 FETCH
#5:c=10000,e=6736,p=0,cr=132,cu=0,mis=0,r=1,dep=1,og=4,tim=1065854501687852 BINDS #5:
EXEC #5:c=0,e=82,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1065854501688065 FETCH
#5:c=0,e=6707,p=0,cr=132,cu=0,mis=0,r=1,dep=1,og=4,tim=1065854501694810 BINDS #5:
EXEC #5:c=0,e=81,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1065854501695011 FETCH
#5:c=10000,e=6699,p=0,cr=132,cu=0,mis=0,r=1,dep=1,og=4,tim=1065854501701747 BINDS #5:
EXEC #5:c=0,e=79,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1065854501701944 FETCH
#5:c=10000,e=6747,p=0,cr=132,cu=0,mis=0,r=1,dep=1,og=4,tim=1065854501708729 BINDS #5:
EXEC #5:c=0,e=80,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1065854501708927 FETCH
#5:c=10000,e=6650,p=0,cr=132,cu=0,mis=0,r=1,dep=1,og=4,tim=1065854501715614 BINDS #5:

---

• mk loop drop table testlio ; create table testlio (n number, v varchar2(1000)) tablespace users; begin for f in 1..30000 loop insert into testlio values (f,'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa'); end loop; end; / create index testlio_i1 on testlio (n) tablespace users;

Jurijs
9268222

---

http://otn.oracle.com/ocm/jvelikanovs.html

---

Please see the official ORACLE-L FAQ: http://www.orafaq.com

---

To unsubscribe send email to: oracle-l-request_at_freelists.org put 'unsubscribe' in the subject line.

--
Archives are at http://www.freelists.org/archives/oracle-l/
FAQ is at http://www.freelists.org/help/fom-serve/cache/1.html
-----------------------------------------------------------------

Received on Mon Aug 02 2004 - 08:28:34 CDT