Oracle FAQ Your Portal to the Oracle Knowledge Grid
HOME | ASK QUESTION | ADD INFO | SEARCH | E-MAIL US
 

Home -> Community -> Usenet -> comp.databases.oracle -> Re: Recursive SQL in a events 10046 trace file

Re: Recursive SQL in a events 10046 trace file

From: Oxmard <shankeyp_at_no-spam.comcast.net>
Date: Thu, 19 Feb 2004 06:39:01 -0600
Message-ID: <QfSdnbS50Yt0MKndRVn-hA@comcast.com>

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.linkname,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" <support_at_dbainfopower.com> wrote in message news:i-ednbMFWsd1DKndRVn-tw_at_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_advice_disclaimer.html
>
>
>
> "Oxmard" <shankeyp_at_no-spam.comcast.net> wrote in message
> news:lvCdnUsdE9Zgwq7dRVn-sw_at_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,tim=43164556217
> > BINDS #3:
> > EXEC

 #3:c=10014,e=33290,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=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.linkname,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,tim=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,tim=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,tim=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,tim=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,tim=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
> >
> >
>
>
Received on Thu Feb 19 2004 - 06:39:01 CST

Original text of this message

HOME | ASK QUESTION | ADD INFO | SEARCH | E-MAIL US