Recursive SQL in a events 10046 trace file

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