By using this site, you agree to our updated Privacy Policy and our Terms of Use. Manage your Cookies Settings.
438,504 Members | 1,884 Online
Bytes IT Community
+ Ask a Question
Need help? Post your question and get tips & solutions from a community of 438,504 IT Pros & Developers. It's quick & easy.

Recursive SQL in a events 10046 trace file

P: n/a
Armed with my new O'Reilly book Optimizing Oracle Performance I have been
trying to get a better understanding of how Oracle works.

The book makes the statement, " A database cal with dep=n + 1 is the
recursive child of the first subsequent dep=n database call listed in the
SQL data stream. The book gives a few examples, and in trying it out it
seemed to work until I tried the following SQL. My question are why does
this not keep with the model? and how does one then account for this
situation:

Dump file c:\oracle\admin\to5\udump\to5_ora_296_2004-02-15a.trc
Sun Feb 15 20:55:22 2004
ORACLE V9.2.0.4.0 - Production vsnsta=0
vsnsql=12 vsnxtr=3
Windows 2000 Version 5.0 Service Pack 4, CPU type 586
Oracle9i Enterprise Edition Release 9.2.0.4.0 - Production
With the Partitioning, OLAP and Oracle Data Mining options
JServer Release 9.2.0.4.0 - Production
Windows 2000 Version 5.0 Service Pack 4, CPU type 586
Instance name: to5

Redo thread mounted by this instance: 1

Oracle process number: 12

Windows thread id: 296, image: ORACLE.EXE
*** 2004-02-15 20:55:22.224
*** SESSION ID:(14.178) 2004-02-15 20:55:22.124
APPNAME mod='SQL*Plus' mh=3669949024 act='' ah=4029777240
=====================
PARSING IN CURSOR #3 len=69 dep=0 uid=60 oct=42 lid=60 tim=43164454230
hv=2004533713 ad='7157ec60'
alter session set events '10046 trace name context forever, level 12'
END OF STMT
EXEC #3:c=0,e=19923,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4, tim=43164321789
WAIT #3: nam='SQL*Net message to client' ela= 8 p1=1952673792 p2=1 p3=0
WAIT #3: nam='SQL*Net message from client' ela= 5029 p1=1952673792 p2=1 p3=0
=====================
PARSING IN CURSOR #3 len=238 dep=0 uid=60 oct=3 lid=60 tim=43164556233
hv=4211298066 ad='7157da00'
select distinct c.name, s.name, s.salesperson_id
from customer c join orders on c.cust_nbr = orders.cust_nbr
join salesperson s on orders.salesperson_id = s.salesperson_id
where c.name = 'Crimson Medical Inc.'
order by s.name, c.NAME
END OF STMT
PARSE #3:c=0,e=2204,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,t im=43164556217
BINDS #3:
EXEC #3:c=10014,e=33290,p=0,cr=0,cu=0,mis=0,r=0,dep=0,o g=4,tim=43164688931
WAIT #3: nam='SQL*Net message to client' ela= 10 p1=1952673792 p2=1 p3=0
FETCH
#3:c=70101,e=66839,p=0,cr=2900,cu=0,mis=0,r=1,dep= 0,og=4,tim=43164785732
WAIT #3: nam='SQL*Net message from client' ela= 754 p1=1952673792 p2=1 p3=0
WAIT #3: nam='SQL*Net message to client' ela= 7 p1=1952673792 p2=1 p3=0
FETCH #3:c=0,e=13248,p=0,cr=0,cu=0,mis=0,r=3,dep=0,og=4, tim=43164823392
WAIT #3: nam='SQL*Net message from client' ela= 3669 p1=1952673792 p2=1 p3=0
STAT #3 id=1 cnt=4 pid=0 pos=1 obj=0 op='SORT UNIQUE (cr=2900 r=0 w=0
time=67115 us)'
STAT #3 id=2 cnt=48 pid=1 pos=1 obj=0 op='NESTED LOOPS (cr=2900 r=0 w=0
time=66511 us)'
STAT #3 id=3 cnt=1440 pid=2 pos=1 obj=0 op='NESTED LOOPS (cr=1458 r=0 w=0
time=40438 us)'
=====================
PARSING IN CURSOR #4 len=116 dep=1 uid=0 oct=3 lid=0 tim=43164909064
hv=431456802 ad='70797038'
select
o.owner#,o.name,o.namespace,o.remoteowner,o.linkna me,o.subname,o.dataobj#,o.
flags from obj$ o where o.obj#=:1
END OF STMT
PARSE #4:c=0,e=1018,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=0,t im=43164909048
BINDS #4:
bind 0: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=08 oacfl2=1 size=24
offset=0
bfp=093dbb5c bln=22 avl=04 flg=05
value=39030
EXEC #4:c=0,e=73894,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4, tim=43165043688
FETCH #4:c=0,e=117,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,ti m=43165056304
STAT #3 id=4 cnt=1440 pid=3 pos=1 obj=39030 op='TABLE ACCESS FULL ORDERS
(cr=16 r=0 w=0 time=5866 us)'
BINDS #4:
bind 0: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=08 oacfl2=1 size=24
offset=0
bfp=093dbb5c bln=22 avl=04 flg=05
value=39034
EXEC #4:c=0,e=50695,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4, tim=43165132543
FETCH #4:c=0,e=116,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,ti m=43165145593
STAT #3 id=5 cnt=1440 pid=3 pos=2 obj=39034 op='TABLE ACCESS BY INDEX ROWID
SALESPERSON (cr=1442 r=0 w=0 time=21449 us)'
STAT #3 id=6 cnt=1440 pid=5 pos=1 obj=39035 op='INDEX UNIQUE SCAN
SALESPERSON_PK (cr=2 r=0 w=0 time=7068 us)'
BINDS #4:
bind 0: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=08 oacfl2=1 size=24
offset=0
bfp=093dbb5c bln=22 avl=04 flg=05
value=39013
EXEC #4:c=0,e=53716,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4, tim=43165240373
FETCH #4:c=0,e=119,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,ti m=43165253961
STAT #3 id=7 cnt=48 pid=2 pos=2 obj=39013 op='TABLE ACCESS BY INDEX ROWID
CUSTOMER (cr=1442 r=0 w=0 time=18732 us)'
STAT #3 id=8 cnt=1440 pid=7 pos=1 obj=39014 op='INDEX UNIQUE SCAN
CUSTOMER_PK (cr=2 r=0 w=0 time=7059 us)'
=====================
PARSING IN CURSOR #3 len=55 dep=0 uid=60 oct=42 lid=60 tim=43165395660
hv=4110456808 ad='71571ff0'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #3:c=0,e=520,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,ti m=43165395645
BINDS #3:
EXEC #3:c=0,e=13838,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4, tim=43165477860
Jul 19 '05 #1
Share this Question
Share on Google+
2 Replies


P: n/a
Ron

Hello Oxmart,

Can you please clarify why do you think recursive depth is not right?

CURSOR #4 seem to be recursive SQL with the depth of 1.

Regards,

Ron
DBA Infopower
http://www.dbainfopower.com
Standard disclaimer:
http://www.dbainfopower.com/dbaip_ad...isclaimer.html

"Oxmard" <sh******@no-spam.comcast.net> wrote in message
news:lv********************@comcast.com...
Armed with my new O'Reilly book Optimizing Oracle Performance I have been
trying to get a better understanding of how Oracle works.

The book makes the statement, " A database cal with dep=n + 1 is the
recursive child of the first subsequent dep=n database call listed in the
SQL data stream. The book gives a few examples, and in trying it out it
seemed to work until I tried the following SQL. My question are why does
this not keep with the model? and how does one then account for this
situation:

Dump file c:\oracle\admin\to5\udump\to5_ora_296_2004-02-15a.trc
Sun Feb 15 20:55:22 2004
ORACLE V9.2.0.4.0 - Production vsnsta=0
vsnsql=12 vsnxtr=3
Windows 2000 Version 5.0 Service Pack 4, CPU type 586
Oracle9i Enterprise Edition Release 9.2.0.4.0 - Production
With the Partitioning, OLAP and Oracle Data Mining options
JServer Release 9.2.0.4.0 - Production
Windows 2000 Version 5.0 Service Pack 4, CPU type 586
Instance name: to5

Redo thread mounted by this instance: 1

Oracle process number: 12

Windows thread id: 296, image: ORACLE.EXE
*** 2004-02-15 20:55:22.224
*** SESSION ID:(14.178) 2004-02-15 20:55:22.124
APPNAME mod='SQL*Plus' mh=3669949024 act='' ah=4029777240
=====================
PARSING IN CURSOR #3 len=69 dep=0 uid=60 oct=42 lid=60 tim=43164454230
hv=2004533713 ad='7157ec60'
alter session set events '10046 trace name context forever, level 12'
END OF STMT
EXEC #3:c=0,e=19923,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4, tim=43164321789
WAIT #3: nam='SQL*Net message to client' ela= 8 p1=1952673792 p2=1 p3=0
WAIT #3: nam='SQL*Net message from client' ela= 5029 p1=1952673792 p2=1 p3=0 =====================
PARSING IN CURSOR #3 len=238 dep=0 uid=60 oct=3 lid=60 tim=43164556233
hv=4211298066 ad='7157da00'
select distinct c.name, s.name, s.salesperson_id
from customer c join orders on c.cust_nbr = orders.cust_nbr
join salesperson s on orders.salesperson_id = s.salesperson_id
where c.name = 'Crimson Medical Inc.'
order by s.name, c.NAME
END OF STMT
PARSE #3:c=0,e=2204,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,t im=43164556217
BINDS #3:
EXEC #3:c=10014,e=33290,p=0,cr=0,cu=0,mis=0,r=0,dep=0,o g=4,tim=43164688931
WAIT #3: nam='SQL*Net message to client' ela= 10 p1=1952673792 p2=1 p3=0
FETCH
#3:c=70101,e=66839,p=0,cr=2900,cu=0,mis=0,r=1,dep= 0,og=4,tim=43164785732
WAIT #3: nam='SQL*Net message from client' ela= 754 p1=1952673792 p2=1 p3=0 WAIT #3: nam='SQL*Net message to client' ela= 7 p1=1952673792 p2=1 p3=0
FETCH #3:c=0,e=13248,p=0,cr=0,cu=0,mis=0,r=3,dep=0,og=4, tim=43164823392
WAIT #3: nam='SQL*Net message from client' ela= 3669 p1=1952673792 p2=1 p3=0 STAT #3 id=1 cnt=4 pid=0 pos=1 obj=0 op='SORT UNIQUE (cr=2900 r=0 w=0
time=67115 us)'
STAT #3 id=2 cnt=48 pid=1 pos=1 obj=0 op='NESTED LOOPS (cr=2900 r=0 w=0
time=66511 us)'
STAT #3 id=3 cnt=1440 pid=2 pos=1 obj=0 op='NESTED LOOPS (cr=1458 r=0 w=0
time=40438 us)'
=====================
PARSING IN CURSOR #4 len=116 dep=1 uid=0 oct=3 lid=0 tim=43164909064
hv=431456802 ad='70797038'
select
o.owner#,o.name,o.namespace,o.remoteowner,o.linkna me,o.subname,o.dataobj#,o. flags from obj$ o where o.obj#=:1
END OF STMT
PARSE #4:c=0,e=1018,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=0,t im=43164909048
BINDS #4:
bind 0: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=08 oacfl2=1 size=24
offset=0
bfp=093dbb5c bln=22 avl=04 flg=05
value=39030
EXEC #4:c=0,e=73894,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4, tim=43165043688
FETCH #4:c=0,e=117,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,ti m=43165056304
STAT #3 id=4 cnt=1440 pid=3 pos=1 obj=39030 op='TABLE ACCESS FULL ORDERS
(cr=16 r=0 w=0 time=5866 us)'
BINDS #4:
bind 0: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=08 oacfl2=1 size=24
offset=0
bfp=093dbb5c bln=22 avl=04 flg=05
value=39034
EXEC #4:c=0,e=50695,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4, tim=43165132543
FETCH #4:c=0,e=116,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,ti m=43165145593
STAT #3 id=5 cnt=1440 pid=3 pos=2 obj=39034 op='TABLE ACCESS BY INDEX ROWID SALESPERSON (cr=1442 r=0 w=0 time=21449 us)'
STAT #3 id=6 cnt=1440 pid=5 pos=1 obj=39035 op='INDEX UNIQUE SCAN
SALESPERSON_PK (cr=2 r=0 w=0 time=7068 us)'
BINDS #4:
bind 0: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=08 oacfl2=1 size=24
offset=0
bfp=093dbb5c bln=22 avl=04 flg=05
value=39013
EXEC #4:c=0,e=53716,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4, tim=43165240373
FETCH #4:c=0,e=119,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,ti m=43165253961
STAT #3 id=7 cnt=48 pid=2 pos=2 obj=39013 op='TABLE ACCESS BY INDEX ROWID
CUSTOMER (cr=1442 r=0 w=0 time=18732 us)'
STAT #3 id=8 cnt=1440 pid=7 pos=1 obj=39014 op='INDEX UNIQUE SCAN
CUSTOMER_PK (cr=2 r=0 w=0 time=7059 us)'
=====================
PARSING IN CURSOR #3 len=55 dep=0 uid=60 oct=42 lid=60 tim=43165395660
hv=4110456808 ad='71571ff0'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #3:c=0,e=520,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,ti m=43165395645
BINDS #3:
EXEC #3:c=0,e=13838,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4, tim=43165477860

Jul 19 '05 #2

P: n/a
The way I had understood the traces to display was due to the way Oracle
dealt with recursive SQL.

If you have an SQL statement that needs to do two actions, for example an
insert that fires a trigger that updates some row in another table. Before
the insert can finish the trigger must finish. So in this case

insert dep 0
|
trigger dep 1
|
update dep 2

The impression I got was when looking at the events 10046 trace data one
would see:

Parsing in Cursor .... dep=2 ...
.....
....
Parsing in Cursor ..... dep=1 ...
....
....
Parsing in Cursor .... dep=0....

In a number of SQL's I did see this pattern, however in the trace data I
provided this was not the case:

PARSING IN CURSOR #3 len=238 dep=0 uid=60 oct=3 lid=60 tim=43164556233
hv=4211298066 ad='7157da00'
select distinct c.name, s.name, s.salesperson_id
from customer c join orders on c.cust_nbr = orders.cust_nbr
join salesperson s on orders.salesperson_id = s.salesperson_id
where c.name = 'Crimson Medical Inc.'
order by s.name, c.NAME
END OF STMT

followed by:

PARSING IN CURSOR #4 len=116 dep=1 uid=0 oct=3 lid=0 tim=43164909064
hv=431456802 ad='70797038'
select

o.owner#,o.name,o.namespace,o.remoteowner,o.linkna me,o.subname,o.dataobj#,o.
flags from obj$ o where o.obj#=:1
END OF STMT

this case seems to be backwards from the way I thought it should work.

"Ron" <su*****@dbainfopower.com> wrote in message
news:i-********************@comcast.com...

Hello Oxmart,

Can you please clarify why do you think recursive depth is not right?

CURSOR #4 seem to be recursive SQL with the depth of 1.

Regards,

Ron
DBA Infopower
http://www.dbainfopower.com
Standard disclaimer:
http://www.dbainfopower.com/dbaip_ad...isclaimer.html

"Oxmard" <sh******@no-spam.comcast.net> wrote in message
news:lv********************@comcast.com...
Armed with my new O'Reilly book Optimizing Oracle Performance I have been trying to get a better understanding of how Oracle works.

The book makes the statement, " A database cal with dep=n + 1 is the
recursive child of the first subsequent dep=n database call listed in the SQL data stream. The book gives a few examples, and in trying it out it
seemed to work until I tried the following SQL. My question are why does
this not keep with the model? and how does one then account for this
situation:

Dump file c:\oracle\admin\to5\udump\to5_ora_296_2004-02-15a.trc
Sun Feb 15 20:55:22 2004
ORACLE V9.2.0.4.0 - Production vsnsta=0
vsnsql=12 vsnxtr=3
Windows 2000 Version 5.0 Service Pack 4, CPU type 586
Oracle9i Enterprise Edition Release 9.2.0.4.0 - Production
With the Partitioning, OLAP and Oracle Data Mining options
JServer Release 9.2.0.4.0 - Production
Windows 2000 Version 5.0 Service Pack 4, CPU type 586
Instance name: to5

Redo thread mounted by this instance: 1

Oracle process number: 12

Windows thread id: 296, image: ORACLE.EXE
*** 2004-02-15 20:55:22.224
*** SESSION ID:(14.178) 2004-02-15 20:55:22.124
APPNAME mod='SQL*Plus' mh=3669949024 act='' ah=4029777240
=====================
PARSING IN CURSOR #3 len=69 dep=0 uid=60 oct=42 lid=60 tim=43164454230
hv=2004533713 ad='7157ec60'
alter session set events '10046 trace name context forever, level 12'
END OF STMT
EXEC #3:c=0,e=19923,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4, tim=43164321789
WAIT #3: nam='SQL*Net message to client' ela= 8 p1=1952673792 p2=1 p3=0
WAIT #3: nam='SQL*Net message from client' ela= 5029 p1=1952673792 p2=1

p3=0
=====================
PARSING IN CURSOR #3 len=238 dep=0 uid=60 oct=3 lid=60 tim=43164556233
hv=4211298066 ad='7157da00'
select distinct c.name, s.name, s.salesperson_id
from customer c join orders on c.cust_nbr = orders.cust_nbr
join salesperson s on orders.salesperson_id = s.salesperson_id
where c.name = 'Crimson Medical Inc.'
order by s.name, c.NAME
END OF STMT
PARSE #3:c=0,e=2204,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,t im=43164556217
BINDS #3:
EXEC #3:c=10014,e=33290,p=0,cr=0,cu=0,mis=0,r=0,dep=0,o g=4,tim=43164688931 WAIT #3: nam='SQL*Net message to client' ela= 10 p1=1952673792 p2=1 p3=0
FETCH
#3:c=70101,e=66839,p=0,cr=2900,cu=0,mis=0,r=1,dep= 0,og=4,tim=43164785732
WAIT #3: nam='SQL*Net message from client' ela= 754 p1=1952673792 p2=1

p3=0
WAIT #3: nam='SQL*Net message to client' ela= 7 p1=1952673792 p2=1 p3=0
FETCH #3:c=0,e=13248,p=0,cr=0,cu=0,mis=0,r=3,dep=0,og=4, tim=43164823392
WAIT #3: nam='SQL*Net message from client' ela= 3669 p1=1952673792 p2=1

p3=0
STAT #3 id=1 cnt=4 pid=0 pos=1 obj=0 op='SORT UNIQUE (cr=2900 r=0 w=0
time=67115 us)'
STAT #3 id=2 cnt=48 pid=1 pos=1 obj=0 op='NESTED LOOPS (cr=2900 r=0 w=0
time=66511 us)'
STAT #3 id=3 cnt=1440 pid=2 pos=1 obj=0 op='NESTED LOOPS (cr=1458 r=0 w=0 time=40438 us)'
=====================
PARSING IN CURSOR #4 len=116 dep=1 uid=0 oct=3 lid=0 tim=43164909064
hv=431456802 ad='70797038'
select

o.owner#,o.name,o.namespace,o.remoteowner,o.linkna me,o.subname,o.dataobj#,o.
flags from obj$ o where o.obj#=:1
END OF STMT
PARSE #4:c=0,e=1018,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=0,t im=43164909048
BINDS #4:
bind 0: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=08 oacfl2=1 size=24 offset=0
bfp=093dbb5c bln=22 avl=04 flg=05
value=39030
EXEC #4:c=0,e=73894,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4, tim=43165043688
FETCH #4:c=0,e=117,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,ti m=43165056304
STAT #3 id=4 cnt=1440 pid=3 pos=1 obj=39030 op='TABLE ACCESS FULL ORDERS
(cr=16 r=0 w=0 time=5866 us)'
BINDS #4:
bind 0: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=08 oacfl2=1 size=24 offset=0
bfp=093dbb5c bln=22 avl=04 flg=05
value=39034
EXEC #4:c=0,e=50695,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4, tim=43165132543
FETCH #4:c=0,e=116,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,ti m=43165145593
STAT #3 id=5 cnt=1440 pid=3 pos=2 obj=39034 op='TABLE ACCESS BY INDEX

ROWID
SALESPERSON (cr=1442 r=0 w=0 time=21449 us)'
STAT #3 id=6 cnt=1440 pid=5 pos=1 obj=39035 op='INDEX UNIQUE SCAN
SALESPERSON_PK (cr=2 r=0 w=0 time=7068 us)'
BINDS #4:
bind 0: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=08 oacfl2=1 size=24 offset=0
bfp=093dbb5c bln=22 avl=04 flg=05
value=39013
EXEC #4:c=0,e=53716,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4, tim=43165240373
FETCH #4:c=0,e=119,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,ti m=43165253961
STAT #3 id=7 cnt=48 pid=2 pos=2 obj=39013 op='TABLE ACCESS BY INDEX ROWID CUSTOMER (cr=1442 r=0 w=0 time=18732 us)'
STAT #3 id=8 cnt=1440 pid=7 pos=1 obj=39014 op='INDEX UNIQUE SCAN
CUSTOMER_PK (cr=2 r=0 w=0 time=7059 us)'
=====================
PARSING IN CURSOR #3 len=55 dep=0 uid=60 oct=42 lid=60 tim=43165395660
hv=4110456808 ad='71571ff0'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #3:c=0,e=520,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,ti m=43165395645
BINDS #3:
EXEC #3:c=0,e=13838,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4, tim=43165477860


Jul 19 '05 #3

This discussion thread is closed

Replies have been disabled for this discussion.