Skip to Main Content
  • Questions
  • No Exection Generated in 10046 Event Trace

Breadcrumb

Question and Answer

Connor McDonald

Thanks for the question, Dan.

Asked: December 08, 2002 - 6:32 pm UTC

Last updated: October 24, 2017 - 3:17 am UTC

Version: 8.1.7

Viewed 1000+ times

You Asked

Hi Tom,

I'm using the event 10046 to trace other sessions. But sometimes I find that there is not execution plan information included in the result trace file. Here is an example:

1. From my session, I executed

dchen@SAPU> exec sys.dbms_system.set_ev(130, 54378, 10046, 8, '')

PL/SQL procedure successfully completed.

2. From another session using SQL*Navigator (sid=130 and serial#=54378), executed

select count(*)
from carrier.sl_conversion_phase p,
carrier.sl_claim_number s,
sap.claims c
where p.reg_office = s.reg_office
and c.claim_number = s.opus#
and c.claim_id in (select claim_id
from sap.sl_spc_claims
where created_by_user_id = 'SLIC'
and policy_coverage_id is null
);

3. then, back to my session, issued
dchen@SAPU> exec sys.dbms_system.set_ev(130, 54378, 10046, 0, '')

PL/SQL procedure successfully completed.

4. ran TKPROF on the trace file ORA03688.TRC, I got

TKPROF: Release 8.1.7.0.0 - Production on Sun Dec 8 16:25:04 2002

(c) Copyright 2000 Oracle Corporation. All rights reserved.

Trace file: ora03688.trc
Sort options: default

********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call
********************************************************************************

select count(*)
from carrier.sl_conversion_phase p,
carrier.sl_claim_number s,
sap.claims c
where p.reg_office = s.reg_office
and c.claim_number = s.opus#
and c.claim_id in (select claim_id
from sap.sl_spc_claims
where created_by_user_id = 'SLIC'
and policy_coverage_id is null
)

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.88 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 19.74 19.82 0 1866464 12 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 5 19.74 20.70 0 1866464 12 1

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



********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.88 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 19.74 19.82 0 1866464 12 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 5 19.74 20.70 0 1866464 12 1

Misses in library cache during parse: 0


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 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 0 0.00 0.00 0 0 0 0

Misses in library cache during parse: 0

2 user SQL statements in session.
0 internal SQL statements in session.
2 SQL statements in session.
********************************************************************************
Trace file: ora03688.trc
Trace file compatibility: 8.00.04
Sort options: default

0 session in tracefile.
2 user SQL statements in trace file.
0 internal SQL statements in trace file.
2 SQL statements in trace file.
1 unique SQL statements in trace file.
60 lines in trace file.

But, if we check the trace shown as follow you can see the execution plan information is there:

*** 2002-12-08 16:19:16.642
WAIT #5: nam='SQL*Net message from client' ela= 50139 p1=1413697536 p2=1 p3=0
STAT #5 id=1 cnt=1 pid=0 pos=0 obj=0 op='SORT AGGREGATE '
STAT #5 id=2 cnt=57 pid=1 pos=1 obj=0 op='NESTED LOOPS '
STAT #5 id=3 cnt=933091 pid=2 pos=1 obj=0 op='HASH JOIN '
STAT #5 id=4 cnt=1026 pid=3 pos=1 obj=0 op='MERGE JOIN CARTESIAN '
STAT #5 id=5 cnt=58 pid=4 pos=1 obj=0 op='VIEW VW_NSO_1 '
STAT #5 id=6 cnt=58 pid=5 pos=1 obj=0 op='SORT UNIQUE '
STAT #5 id=7 cnt=57 pid=6 pos=1 obj=96712 op='TABLE ACCESS FULL SL_SPC_CLAIMS '
STAT #5 id=8 cnt=1026 pid=4 pos=2 obj=0 op='SORT JOIN '
STAT #5 id=9 cnt=18 pid=8 pos=1 obj=54410 op='TABLE ACCESS FULL SL_CONVERSION_PHASE '
STAT #5 id=10 cnt=16394 pid=3 pos=2 obj=52985 op='TABLE ACCESS FULL SL_CLAIM_NUMBER '
STAT #5 id=11 cnt=57 pid=2 pos=2 obj=99323 op='INDEX RANGE SCAN '
WAIT #1: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 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
WAIT #1: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0
=====================
PARSING IN CURSOR #1 len=366 dep=0 uid=44 oct=3 lid=44 tim=14735176 hv=876398650 ad='1297c6e4'
select count(*)
from carrier.sl_conversion_phase p,
carrier.sl_claim_number s,
sap.claims c
where p.reg_office = s.reg_office
and c.claim_number = s.opus#
and c.claim_id in (select claim_id
from sap.sl_spc_claims
where created_by_user_id = 'SLIC'
and policy_coverage_id is null
)
END OF STMT
PARSE #1:c=0,e=44,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=14735217
WAIT #1: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #1: nam='SQL*Net message from client' ela= 2 p1=1413697536 p2=1 p3=0
WAIT #5: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #5: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0
=====================
PARSING IN CURSOR #5 len=366 dep=0 uid=44 oct=3 lid=44 tim=14735237 hv=876398650 ad='1297c6e4'
select count(*)
from carrier.sl_conversion_phase p,
carrier.sl_claim_number s,
sap.claims c
where p.reg_office = s.reg_office
and c.claim_number = s.opus#
and c.claim_id in (select claim_id
from sap.sl_spc_claims
where created_by_user_id = 'SLIC'
and policy_coverage_id is null
)
END OF STMT
PARSE #5:c=0,e=44,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=14735278
WAIT #5: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #5: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0
EXEC #5:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=14735287
*** 2002-12-08 16:19:38.095
WAIT #5: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
FETCH #5:c=1974,e=1982,p=0,cr=1866464,cu=12,mis=0,r=1,dep=0,og=4,tim=14737272
WAIT #5: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0
FETCH #5:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=14737278
WAIT #5: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0

If I use SQL_TRACE to trace the same query from my owner session, I can get the execution plan information in the TKPROF output report.
Here is the SQL_TRACE output from TKPROF:

TKPROF: Release 8.1.7.0.0 - Production on Sun Dec 8 15:48:31 2002

(c) Copyright 2000 Oracle Corporation. All rights reserved.

Trace file: ora03952.trc
Sort options: default

********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call
********************************************************************************

alter session set sql_trace=true


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

Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer goal: CHOOSE
Parsing user id: 44
********************************************************************************

select count(*)
from carrier.sl_conversion_phase p,
carrier.sl_claim_number s,
sap.claims c
where p.reg_office = s.reg_office
and c.claim_number = s.opus#
and c.claim_id in (select claim_id
from sap.sl_spc_claims
where created_by_user_id = 'SLIC'
and policy_coverage_id is null
)

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.48 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 19.99 19.98 0 1866464 12 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 19.99 20.46 0 1866464 12 1

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

Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE
57 NESTED LOOPS
933091 HASH JOIN
1026 MERGE JOIN CARTESIAN
58 VIEW VW_NSO_1
58 SORT UNIQUE
57 TABLE ACCESS FULL SL_SPC_CLAIMS
1026 SORT JOIN
18 TABLE ACCESS FULL SL_CONVERSION_PHASE
16394 TABLE ACCESS FULL SL_CLAIM_NUMBER
57 INDEX RANGE SCAN (object id 99323)

********************************************************************************

alter session set sql_trace=false


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

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



********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.61 0 0 0 0
Execute 3 0.00 0.59 0 0 0 0
Fetch 2 19.99 19.98 0 1866464 12 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 7 19.99 21.18 0 1866464 12 1

Misses in library cache during parse: 2
Misses in library cache during execute: 1


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 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 0 0.00 0.00 0 0 0 0

Misses in library cache during parse: 0

3 user SQL statements in session.
0 internal SQL statements in session.
3 SQL statements in session.
********************************************************************************
Trace file: ora03952.trc
Trace file compatibility: 8.00.04
Sort options: default

1 session in tracefile.
3 user SQL statements in trace file.
0 internal SQL statements in trace file.
3 SQL statements in trace file.
3 unique SQL statements in trace file.
63 lines in trace file.

Here are my questions:

1. Why dose tkprof ignore the execution plan in the trace file generated from event 10046 in some cases? I know it won't recognize those waits related information but not STATS related information.

2. In the case shown in my case, the event 10046 generated two sections in the trace file for the same query statement. I only issued it once. Therefore, we got 2 counts of parses. How could this happan?

Thanks.


and Connor said...

1) trace files are linear -- the stat records you show are for some "other cursor #5" -- no the cursor #5 you show. The stat records are only printed out when the cursor is closed -- I believe the other session you are monitoring is keeping the cursor open (hence the stat records won't make it out)

2) sql navigator must "parse the query" in order to describe it (cause their programmers didn't know how to program Oracle) and then they parse it (wastefully) again in order to execute and display it.

SQL_TRACE shows you reality - navigator is parsing the query two times.


so, here is what i think - you ran the query in navigator. THEN you enabled trace. THEN you ran again in navigator. navigator closed the other query -- that dumped the stats records (for the PREVIOUS execution of that query). navigator then parsed the query -- to describe it. navigator then parsed and executed the query in order to print it. then you turned off trace -- hence NO stats records for that cursor.

Rating

  (11 ratings)

Is this answer out of date? If it is, please let us know via a Comment

Comments

Does it mean SQL Navigator tool has problems

Ajeet, December 09, 2002 - 1:50 am UTC

Tom - you said - sql navigator must "parse the query" in order to describe it (cause their
programmers didn't know how to program Oracle) and then they parse it
(wastefully) again in order to execute and display it.
Does it mean that SQL Navigator is doing wrong because of the way it has been designed and develop?
In my company few programmers use this tool extensively-should we check the trace files to ensure that we are using resources in optimum way.
Thanks for your advice on this.


Tom Kyte
December 09, 2002 - 7:27 am UTC

If you see a double parse on every execute, they are wasting resources -- yes. There should be AT WORST a 1-1 ratio between parse and execute. At best (but very hard to do with a generic tool like navigator), a 1 parse to N executes where N > 1.

Dan Chen, December 09, 2002 - 12:56 pm UTC

Thank you very much, Tom. Your answers help me to understand what's behind the scene. I think that's why I always get some thing more than what it dose from sql*plus when I use the way learned from your book and this site about how to create a test harnes.
Thanks.

-Dan

Additional caveat

Mark A. Williams, December 09, 2002 - 8:05 pm UTC

Don't know if this caveat applies here, but if you are using the Oracle ADO/OLEDB provider to connect to the server, search MetaLink for bug #1727475 (which is fixed in the Oracle 9.2 provider)...

Here is a short excerpt from Oracle Support in one of the posts:

"Apparently what is happening is the provider (ADO/OLEDB)calls OCIStmtExecute twice. Once with DESCRIBE_ONLY to do an explicit describe and again to execute. The parse stat count is being incremented twice, once for each execute call. The parse happens only during the first call which is a hard parse. On the second call, the count is being incremented even though a hard parse is not made. As a result, the parse count shows 2 even though it is actually being parsed only once, the first time."

Just thought I'd throw that out there just in case...

- Mark

What are the parameters passed to DBMS_SYSTEM.SET_EV?

Matt, February 10, 2003 - 12:34 am UTC

DESC DBMS_SYSTEM

PROCEDURE SET_EV
Argument Name Type In/Out Default?
------------------------------ ----------------------- ------ --------
SI BINARY_INTEGER IN
SE BINARY_INTEGER IN
EV BINARY_INTEGER IN
LE BINARY_INTEGER IN
NM VARCHAR2 IN

Are these:

SI - V$SESSION.SID
SE - V$SESSION.SERIAL#
EV - Event Number eg: 10046
LE - Level eg: 1 (SQL_TRACE),
4 (SQL_TRACE+BINDS),
8 (SQL_TRACE+WAITS),
or 12(SQL_TRACE+BINDS+WAITS)
NM - ??????

What is NM?

I am looking to set tracing (SQL_TRACE + WAITS) from another session.

Regards,

Tom Kyte
February 10, 2003 - 7:46 am UTC

it is the "name" which is not used with the 10046 trace. Just pass ''

you guessed right on the rest.

How do you switch this off for a session?

Matt, February 10, 2003 - 5:34 pm UTC

The other question is of course that after switching on tracing using, for example:

execute sys.dbms_system.set_ev(18,13,10046,8,'')

If the session is long running, how do I switch the tracing off after some period?

Would execute sys.dbms_system.set_ev(18,13,10046,0,'') do this?

Regards


Tom Kyte
February 11, 2003 - 7:59 am UTC

when you tried it, what did it do?

yes, setting to zero turns it off.

No Explain Plan In the TKProf Output.

Ganesh Raja, December 09, 2003 - 3:10 am UTC

Hi Tom,

I dont get an explain plan when i run my Trace file Thru Tkprof.

What may be the Reasons for that ..

Regards,
Ganesh R

Tom Kyte
December 09, 2003 - 6:30 am UTC

no version?

did you exit the application that generated the trace, the STAT records only get written when the cursor is closed, if the application keeps cursors open (eg: it was well written), you must exit the application.


you can use explain=u/p on the tkprof command line, but I don't like that -- the explain plan might well not be the one that was actually used at run time.

Query on trace

vivek Saxena, January 19, 2004 - 11:56 am UTC

Tom,
During the performance testing ( via Load runner ) our client had complained that our application is "SLOW". They are looking for 3200 records/hour and at present we are getting only 2000/hrs. So i have traced a session in our office and come up with following result. What i am not understood is why i am getting parse/exec/fetch for SYS.ALL_ARGUMENTS every time oracle tried to run procedure from a package. Our application has packages containing many procedure with in it.
Here is text from my trace.

=====================
PARSING IN CURSOR #1 len=165 dep=0 uid=45 oct=3 lid=45 tim=94659226 hv=106591048 ad='422ce00'
SELECT UNIQUE POSITION, DATA_TYPE, IN_OUT FROM SYS.ALL_ARGUMENTS WHERE OBJECT_ID = 31455 AND OBJECT_NAME = 'SP_ATTENDEE_TYPE' AND DATA_LEVEL=0 ORDER BY POSITION DESC
END OF STMT
PARSE #1:c=3,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=94659229
EXEC #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=94659229
FETCH #1:c=1,e=2,p=0,cr=15,cu=0,mis=0,r=1,dep=0,og=4,tim=94659231
=====================
PARSING IN CURSOR #39 len=50 dep=0 uid=45 oct=47 lid=45 tim=94659231 hv=883693539 ad='422be94'
BEGIN PKG_RBK_COMMON.SP_ATTENDEE_TYPE ( :V1); END;
END OF STMT
PARSE #39:c=4,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=94659234
=====================
PARSING IN CURSOR #47 len=65 dep=1 uid=42 oct=3 lid=42 tim=94659235 hv=831795434 ad='47efc1c'
SELECT ATTEND_TYPE FROM RM_ATTENDTYPE ORDER BY ATTEND_TYPE DESC
END OF STMT
PARSE #47:c=3,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=94659237
EXEC #47:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=94659237
EXEC #39:c=4,e=5,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=4,tim=94659239
FETCH #47:c=0,e=0,p=0,cr=1,cu=0,mis=0,r=5,dep=0,og=4,tim=94659239
STAT #47 id=1 cnt=5 pid=0 pos=0 obj=31579 op='INDEX FULL SCAN DESCENDING '
XCTEND rlbk=0, rd_only=1
STAT #1 id=1 cnt=1 pid=0 pos=0 obj=0 op='SORT ORDER BY '
STAT #1 id=2 cnt=1 pid=1 pos=1 obj=0 op='SORT UNIQUE '
STAT #1 id=3 cnt=1 pid=2 pos=1 obj=0 op='FILTER '
STAT #1 id=4 cnt=2 pid=3 pos=1 obj=0 op='NESTED LOOPS '
STAT #1 id=5 cnt=2 pid=4 pos=1 obj=0 op='NESTED LOOPS '
STAT #1 id=6 cnt=2 pid=5 pos=1 obj=18 op='TABLE ACCESS BY INDEX ROWID OBJ$ '
STAT #1 id=7 cnt=2 pid=6 pos=1 obj=33 op='INDEX UNIQUE SCAN '
STAT #1 id=8 cnt=2 pid=5 pos=2 obj=22 op='TABLE ACCESS CLUSTER USER$ '
STAT #1 id=9 cnt=2 pid=8 pos=1 obj=11 op='INDEX UNIQUE SCAN '
STAT #1 id=10 cnt=2 pid=4 pos=2 obj=63 op='TABLE ACCESS BY INDEX ROWID ARGUMENT$ '
STAT #1 id=11 cnt=4 pid=10 pos=1 obj=108 op='INDEX RANGE SCAN '
STAT #1 id=13 cnt=1 pid=3 pos=3 obj=0 op='NESTED LOOPS '
STAT #1 id=14 cnt=2 pid=13 pos=1 obj=0 op='FIXED TABLE FULL X$KZSRO '
STAT #1 id=15 cnt=2 pid=13 pos=2 obj=82 op='TABLE ACCESS BY INDEX ROWID OBJAUTH$ '
STAT #1 id=16 cnt=2 pid=15 pos=1 obj=101 op='INDEX RANGE SCAN '
STAT #1 id=12 cnt=1 pid=3 pos=2 obj=0 op='FIXED TABLE FULL X$KZSPR '
=====================
PARSING IN CURSOR #1 len=69 dep=0 uid=45 oct=47 lid=45 tim=94659254 hv=1302911214 ad='56e5370'
begin dbms_utility.name_resolve(:v1,:v2,:v3,:v4,:v5,:v6,:v7,:v8);end;
END OF STMT
PARSE #1:c=2,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=94659256
EXEC #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=4,tim=94659257
=====================
PARSING IN CURSOR #1 len=168 dep=0 uid=45 oct=3 lid=45 tim=94659259 hv=4229066408 ad='4288c3c'
SELECT UNIQUE POSITION, DATA_TYPE, IN_OUT FROM SYS.ALL_ARGUMENTS WHERE OBJECT_ID = 31451 AND OBJECT_NAME = 'SP_ATTENDEE_DETAILS' AND DATA_LEVEL=0 ORDER BY POSITION DESC
END OF STMT
PARSE #1:c=4,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=94659260
EXEC #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=94659260
FETCH #1:c=0,e=0,p=0,cr=18,cu=0,mis=0,r=3,dep=0,og=4,tim=94659262
=====================
PARSING IN CURSOR #38 len=66 dep=0 uid=45 oct=47 lid=45 tim=94659264 hv=879131564 ad='4279c88'
BEGIN PKG_RBK_DETAILS.SP_ATTENDEE_DETAILS ( :V1, :V2, :V3); END;
END OF STMT
PARSE #38:c=3,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=94659265
=====================
PARSING IN CURSOR #47 len=727 dep=1 uid=42 oct=3 lid=42 tim=94659267 hv=801113033 ad='44af3e4'
SELECT RM_ATTENDEE.ADD_COMMENTS,RM_ATTENDEE.ATTEND_TYPE,RM_ATTENDEE.AUTO_NUMBER,RM_ATTENDEE.BL_ID,RM_ATTENDEE.BOOKING_ID,RM_ATTENDEE.CONTACT_TEL,RM_ATTENDEE.DATE_CREATED,RM_ATTENDEE.DATE_OF_VISIT,RM_ATTENDEE.INT_CONTACT,RM_ATTENDEE.NAME_FIRST,RM_ATTENDEE.NAME_LAST,RM_ATTENDEE.REQUEST_ID,RM_ATTENDEE.STATUS,RM_ATTENDEE.TIME_CREATED,RM_ATTENDEE.TIME_EXPECTED,RM_ATTENDEE.VISITOR_PASS,RM_ATTENDEE.TIME_IN,RM_ATTENDEE.TIME_OUT,EM.NAME_LAST CONTACTNAMELAST,EM.NAME_FIRST CONTACTNAMEFIRST FROM RM_ATTENDEE,EM WHERE RM_ATTENDEE.REQUEST_ID = :b1 AND RM_ATTENDEE.BOOKING_ID = :b2 AND RM_ATTENDEE.INT_CONTACT = EM.EM_ID (+) ORDER BY RM_ATTENDEE.DATE_OF_VISIT,RM_ATTENDEE.TIME_EXPECTED,RM_ATTENDEE.NAME_LAST,RM_ATTENDEE.NAME_FIRST
END OF STMT
PARSE #47:c=3,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=94659268
EXEC #47:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=94659270
EXEC #38:c=5,e=5,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=4,tim=94659270
FETCH #47:c=0,e=0,p=0,cr=4,cu=4,mis=0,r=1,dep=0,og=4,tim=94659271
STAT #47 id=1 cnt=1 pid=0 pos=0 obj=0 op='SORT ORDER BY '
STAT #47 id=2 cnt=1 pid=1 pos=1 obj=0 op='NESTED LOOPS OUTER '
STAT #47 id=3 cnt=2 pid=2 pos=1 obj=31580 op='TABLE ACCESS FULL RM_ATTENDEE '
STAT #47 id=4 cnt=1 pid=2 pos=2 obj=25150 op='TABLE ACCESS BY INDEX ROWID EM '
STAT #47 id=5 cnt=2 pid=4 pos=1 obj=25159 op='INDEX UNIQUE SCAN '
XCTEND rlbk=0, rd_only=1
STAT #2 id=1 cnt=1 pid=0 pos=0 obj=27191 op='TABLE ACCESS BY INDEX ROWID CDATA '
STAT #2 id=2 cnt=2 pid=1 pos=1 obj=27192 op='INDEX UNIQUE SCAN '
=====================


This happens every time a procedure is called.

Please help.

Vivek


Tom Kyte
January 19, 2004 - 1:04 pm UTC

probably using odbc eh? what is the client.

query on trace

vivek, January 19, 2004 - 3:35 pm UTC

Its a Cold fusion MX application and uses JDBC connection using oracle type IV driver. Oracle database version is 8.1.7.


Tom Kyte
January 19, 2004 - 3:56 pm UTC

what version of type iv driver.

query

vivek, January 19, 2004 - 4:57 pm UTC

Tom,

I think its JDBC Thin Driver 8.1.7 as we have used class12.zip , to create it.

thanks




Tom Kyte
January 20, 2004 - 6:57 am UTC

can you try a later version. I vaguely recall a performance issue with that view in the really old stuff.

it is basically describing the stored procedure.

reader

A reader, November 23, 2007 - 10:33 am UTC

When I run a program it takes about 3 to 4 hours to complete. The program starts running fast and then gradually slows down in performance

I like to take trace when it runs fast

Then like to run a trace when it is slow

I am using dbms_system.set_ev

When I take 2 traces, it writes to the same trace file and the stats average out. This is windows systems rdbms 10.2. Is there a way collect stats seperately just for each execution of dbms_system.set_ev. Is it possible. If it is not possible, how to analyze different stats at different intervals. Th etrace files become large with WAIT stats
Tom Kyte
November 26, 2007 - 11:24 am UTC

not unless the program itself cooperates - and you are on 10g.

or, you could try:

a) turn it on
b) turn it off
c) copy trace file

d) turn it on
e) turn it off
f) using (c), remove those lines from the trace file

now you have (c) and (f') to tkprof.

10046 Event Trace enable

Dhananjay Sondur, October 22, 2017 - 11:40 am UTC

HI Tom,

Thanks for your great effort to maintain this site more informative and sharing knowledge.

could you please share the steps to enable 10046 trace at next session level(eg. if DBA needs to monitor the trace of Developer session).

Thanks,
Dhananjay


Connor McDonald
October 24, 2017 - 3:17 am UTC

1) exec dbms_monitor.session_trace_enable(sid,serial#,waits=>true,binds=>true);

2) run program

3) exec dbms_monitor.session_trace_disable(sid,serial#);

This creates a trace file. Here's a video on how to locate it.


More to Explore

PL/SQL demos

Check out more PL/SQL tutorials on our LiveSQL tool.

PL/SQL docs

PL/SQL reference manual from the Oracle documentation library