Thanks for your reply, Daniel.
Yes, it makes sense for the EXEC calls, but it doesn't
explain the PARSEs, does it?
PARSING IN CURSOR #1 len=94 dep=0...
PARSE #1:c=0,e=141,p=0,cr=0,cu=0,mis=0,r=0,dep=0...
PARSING IN CURSOR #2 len=68 dep=1...
PARSE #2:c=0,e=60,p=0,cr=0,cu=0,mis=0,r=0,dep=1...
Here I presume elapsed time of the PL/SQL call is
141-60=81 microsec, but it doesn't follow the same
rule of parent db call following the recursive/child
one - it is out of sequence.
It is even more interesting with FETCHes. I can't seem
to find FETCH call for the parent anywhere in the
trace file. Maybe it makes sense to omit this call
altogether as time tallied against PL/SQL proc call
goes to EXEC anyway, but than again it breaks the
rule.
And no, I don't think it is a trace activation/data
collection error as these parent-child cursors appear
in the middle of the trace.
Thanks again,
Boris Dali.
- Daniel Fink <Daniel.Fink_at_Sun.COM> wrote: > Boris,
>
> Cary is correct. It gets a little confusing,
> especially with pl/sql
> involved. It also helps to remember to differentiate
> between database
> calls (parse/execute/fetch) and other events
> (wait/stat).
>
> Using your example below, I'll attempt an
> explanation inline.
>
> Daniel Fink
>
> Boris Dali wrote:
>
> > Reading Cary's "Optimizing Oracle Performance",
> page
> > 91 it says:
> > "A database call with dep=n+1 is the recursive
> child
> > of the first SUBSEQUENT (empasis mine) dep=n
> database
> > call listed in the SQL trace data stream"
> >
> > Does this apply to the SQL issued from PL/SQL?
> >
> > I am looking at the simple packaged stored proc:
> >
> > PACKAGE BODY nav_tree_pkg is
> > PROCEDURE GET_NAV_PARENT_NODE_ID
> > ( p_NodeId IN NUMBER,
> > p_ParentNodeId OUT NUMBER)
> > IS
> > BEGIN
> > SELECT PARENT_NAV_NODE_ID INTO p_ParentNodeId
> > FROM NAV_NODE
> > WHERE NAV_NODE_ID = p_NodeId;
> > EXCEPTION
> > WHEN NO_DATA_FOUND THEN
> > p_ParentNodeId := -1 ;
> > END; -- Procedure
> > END;
> >
> > ... and here's what I see in the trace (sorry the
> > lines are probably wrapped):
> >
> > =====================
> > PARSING IN CURSOR #1 len=94 dep=0 uid=83 oct=47
> lid=83
> > tim=1617285502494 hv=1138148843 ad='605d0998'
> > BEGIN nav_tree_pkg.get_nav_parent_node_id(
> > :p_nodeid,
> > :p_parentnodeid
> > );
> > END;
> >
> > END OF STMT
> > PARSE
>
#1:c=0,e=141,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1617285502483
> >
> > BINDS #1: bind 0: dty=2 mxl=22(22) mal=00 scl=00
> pre=00
> > oacflg=01 oacfl2=0 size=48 offset=0
> > bfp=800003fbc005ff80 bln=22 avl=01 flg=05
> > value=0
> > bind 1: dty=2 mxl=22(22) mal=00 scl=00 pre=00
> > oacflg=01 oacfl2=0 size=0 offset=24
> > bfp=800003fbc005ff98 bln=22 avl=00 flg=01
> > =====================
>
> Here, the pl/sql block is parsed. The next step in
> the statement process
> is to execute the statement (parse/execute/fetch).
> However, notice that
> EXEC #1 is not the next database call.
>
> >
> > PARSING IN CURSOR #2 len=68 dep=1 uid=98 oct=3
> lid=98
> > tim=1617285503241 hv=1778717541 ad='606795e8'
> > SELECT PARENT_NAV_NODE_ID FROM NAV_NODE
> > WHERE NAV_NODE_ID = :b1
> > END OF STMT
> > PARSE
>
#2:c=0,e=60,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1617285503230
> > BINDS #2:
> > bind 0: dty=2 mxl=22(21) mal=00 scl=00 pre=00
> > oacflg=03 oacfl2=4000000000000001 size=24 offset=0
> > bfp=800003fbc005f660 bln=22 avl=01 flg=05
> > value=0
>
> Okay, here we parse the sql statement inside the
> block. In the next
> couple of db calls, we do the execute/fetch of
> Cursor #2.
>
> >
> > EXEC
>
#2:c=0,e=151,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1617285503563
> > FETCH
> >
>
#2:c=0,e=40,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=1617285503648
> > WAIT #1: nam='SQL*Net message to client' ela= 2
> > p1=1413697536 p2=1 p3=0
> > EXEC
>
#1:c=0,e=1037,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=4,tim=1617285503786
>
> Here is the execute database call for the block. It
> is the execution of
> the block that motivates the parse/execute/fetch of
> the inner statement.
>
> >
> > WAIT #1: nam='SQL*Net message from client' ela=
> 2470
> > p1=1413697536 p2=1 p3=0
> > =====================
> > ... Totaly different calls
> > =====================
> >
> > So here it looks like the child CURSOR #2 with
> dep=1
> > is emitted AFTER the parent (CURSOR #1, dep=0)
> >
> > Thanks,
> > Boris Dali.
Post your free ad now!
http://personals.yahoo.ca
--
Please see the official ORACLE-L FAQ: http://www.orafaq.net
--
Author: Boris Dali
INET: boris_dali_at_yahoo.ca
Fat City Network Services -- 858-538-5051 http://www.fatcity.com
San Diego, California -- Mailing list and web hosting services
---------------------------------------------------------------------
To REMOVE yourself from this mailing list, send an E-Mail message
to: ListGuru_at_fatcity.com (note EXACT spelling of 'ListGuru') and in
the message BODY, include a line containing: UNSUB ORACLE-L
(or the name of mailing list you want to be removed from). You may
also send the HELP command for other information (like subscribing).
Received on Tue Nov 25 2003 - 19:29:25 CST
