Re: [Fwd: Re: 10046 trace - unaccounted for time]

That doesn't make much sense.

Insert statment is inserting with a lob size of 3880 bytes and returning that column of 3880 bytes.
For cursor #11:
PARSE has timestamp of tim=5188376807523 and EXC has timestamp of tim=5188376817822.
difference is 10291 micros, which is close enough to 10076 micros printed in EXEC stats.

Followed by waits for cursor #12, which is not an insert statement. But, wait is for 'sql*Net more data from client' which is a typical wait if there is huge amount of data being passed from the client.

So sequence of waits are: Almost looks like huge amount of data is passed from the client. Also, it is possible that due to rounding errors, time is not properly accounted in tkprof.

2 sqlnet more data
1 lob write
6 more sqlnet data from client..
1 lob read
8 more sqlnet data from client..
1 single block read p1=232 p2=113031 p3=1 8 more sqlnet data from client..
1 single block read p1=232 p2=113032 p3=1 8 more sqlnet data from client..
1 latch free. p2=98

Keith,
  Can you please find what block is file 232, block 113031 and 113032 ? What version of Oracle is this? Also, if you could send me raw trace file, that will be great..

Cheers
Riyaj
The Pythian group : www.pythian.com
blog: http://orainternals.wordpress.com

Keith Moore wrote:
> Ok, we got our test system setup and turned on system wide tracing and now
> have the SQL statement where the hang occurs. The statement is querying
> all_constraints but it is not recursive SQL. It is being called from the
> application.
>
> Below is a relevant section of the trace file. It looks like it reuses CURSOR
> #12 but the 2nd query is on cdef$ which is also related to constraints. Not
> sure I understand that.
>
> It's also still not clear to me whether the unaccounted for time is for Cursor
> #12 or Cursor #11 or from something outside this session.
>
> This problem has now been reproduced on a 2nd server with a duplicate of the
> database. This server is very lightly loaded so I don't think it is server
> related.
>
> Keith
> ...
> =====================
> PARSING IN CURSOR #11 len=117 dep=0 uid=19 oct=2 lid=19 tim=5188376807531
> hv=157606933 ad='ea888d70'
> INSERT INTO "PWRLINE"."LSCHANNELCUTDATA" ("UIDCHANNELCUT","VALUECODES") VALUES
> (:1,:2) RETURNING "VALUECODES" INTO :3
> END OF STMT
> PARSE #11:c=10000,e=2818,p=0,cr=2,cu=0,mis=1,r=0,dep=0,og=0,tim=5188376807523
> BINDS #11:
> bind 0: dty=2 mxl=22(21) mal=00 scl=00 pre=00 oacflg=07 oacfl2=0 size=24
> offset=0
> bfp=1033b9438 bln=22 avl=06 flg=05
> value=151091971
> bind 1: dty=113 mxl=3876(3876) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0
> size=3880 offset=0
> bfp=1033b84f8 bln=3876 avl=86 flg=05
> value=
> Dump of memory from 0x00000001033B84F8 to 0x00000001033B854E
> 1033B84F0 00540000 00180000 [.T......]
> 1033B8500 00000000 00000000 00000000 00000000 [................]
> Repeat 3 times
> 1033B8540 00000000 00000000 00000000 00008558 [...............X]
> bind 2: dty=113 mxl=3876(3876) mal=00 scl=00 pre=00 oacflg=05 oacfl2=0
> size=3880 offset=0
> bfp=1033d25e0 bln=3876 avl=00 flg=05
> WAIT #11: nam='db file sequential read' ela= 6853 p1=231 p2=107273 p3=1
> WAIT #11: nam='SQL*Net message to client' ela= 3 p1=1413697536 p2=1 p3=0
> EXEC #11:c=0,e=10076,p=1,cr=1,cu=7,mis=0,r=1,dep=0,og=4,tim=5188376817822
> WAIT #11: nam='SQL*Net message from client' ela= 7376 p1=1413697536 p2=1 p3=0
> WAIT #12: nam='SQL*Net more data from client' ela= 56 p1=1413697536 p2=118 p3=0
> WAIT #12: nam='SQL*Net more data from client' ela= 31 p1=1413697536 p2=13 p3=0
> *** 2008-08-06 15:38:28.867
> WAIT #12: nam='db file sequential read' ela= 1745 p1=232 p2=113030 p3=1
> *** 2008-08-06 15:38:45.859
> WAIT #12: nam='direct path write (lob)' ela= 605 p1=63 p2=48670 p3=1
> WAIT #12: nam='SQL*Net more data from client' ela= 109 p1=1413697536 p2=140 p3=0
> WAIT #12: nam='SQL*Net more data from client' ela= 24 p1=1413697536 p2=151 p3=0
> WAIT #12: nam='SQL*Net more data from client' ela= 23 p1=1413697536 p2=162 p3=0
> WAIT #12: nam='SQL*Net more data from client' ela= 20 p1=1413697536 p2=173 p3=0
> WAIT #12: nam='SQL*Net more data from client' ela= 21 p1=1413697536 p2=184 p3=0
> WAIT #12: nam='SQL*Net more data from client' ela= 19 p1=1413697536 p2=195 p3=0
> WAIT #12: nam='direct path read (lob) ' ela= 7952 p1=63 p2=48670 p3=1
> WAIT #12: nam='SQL*Net more data from client' ela= 38 p1=1413697536 p2=206 p3=0
> WAIT #12: nam='SQL*Net more data from client' ela= 21 p1=1413697536 p2=217 p3=0
> WAIT #12: nam='SQL*Net more data from client' ela= 22 p1=1413697536 p2=228 p3=0
> WAIT #12: nam='SQL*Net more data from client' ela= 18 p1=1413697536 p2=239 p3=0
> WAIT #12: nam='SQL*Net more data from client' ela= 21 p1=1413697536 p2=250 p3=0
> WAIT #12: nam='SQL*Net more data from client' ela= 18 p1=1413697536 p2=5 p3=0
> WAIT #12: nam='SQL*Net more data from client' ela= 20 p1=1413697536 p2=16 p3=0
> WAIT #12: nam='SQL*Net more data from client' ela= 17 p1=1413697536 p2=27 p3=0
> *** 2008-08-06 15:40:04.003
> WAIT #12: nam='db file sequential read' ela= 9247 p1=232 p2=113031 p3=1
> *** 2008-08-06 15:40:21.566
> WAIT #12: nam='SQL*Net more data from client' ela= 148 p1=1413697536 p2=38 p3=0
> WAIT #12: nam='SQL*Net more data from client' ela= 31 p1=1413697536 p2=49 p3=0
> WAIT #12: nam='SQL*Net more data from client' ela= 29 p1=1413697536 p2=60 p3=0
> WAIT #12: nam='SQL*Net more data from client' ela= 23 p1=1413697536 p2=71 p3=0
> WAIT #12: nam='SQL*Net more data from client' ela= 26 p1=1413697536 p2=82 p3=0
> WAIT #12: nam='SQL*Net more data from client' ela= 22 p1=1413697536 p2=93 p3=0
> WAIT #12: nam='SQL*Net more data from client' ela= 27 p1=1413697536 p2=104 p3=0
> WAIT #12: nam='SQL*Net more data from client' ela= 21 p1=1413697536 p2=115 p3=0
> *** 2008-08-06 15:41:33.474
> WAIT #12: nam='db file sequential read' ela= 9106 p1=232 p2=113032 p3=1
> *** 2008-08-06 15:42:00.517
> WAIT #12: nam='SQL*Net more data from client' ela= 78 p1=1413697536 p2=126 p3=0
> WAIT #12: nam='SQL*Net more data from client' ela= 25 p1=1413697536 p2=137 p3=0
> WAIT #12: nam='SQL*Net more data from client' ela= 46 p1=1413697536 p2=148 p3=0
> WAIT #12: nam='SQL*Net more data from client' ela= 783 p1=1413697536 p2=159 p3=0
> WAIT #12: nam='SQL*Net more data from client' ela= 74 p1=1413697536 p2=170 p3=0
> WAIT #12: nam='SQL*Net more data from client' ela= 38 p1=1413697536 p2=181 p3=0
> WAIT #12: nam='SQL*Net more data from client' ela= 31 p1=1413697536 p2=192 p3=0
> WAIT #12: nam='SQL*Net more data from client' ela= 24 p1=1413697536 p2=203 p3=0
> *** 2008-08-06 15:43:04.069
> WAIT #12: nam='latch free' ela= 6 p1=16749741904 p2=98 p3=0
> WAIT #12: nam='db file sequential read' ela= 1385 p1=232 p2=113033 p3=1
> *** 2008-08-06 15:43:40.956
> WAIT #12: nam='SQL*Net more data from client' ela= 129 p1=1413697536 p2=214 p3=0
> WAIT #12: nam='SQL*Net more data from client' ela= 27 p1=1413697536 p2=225 p3=0
>

.. snippped

--
http://www.freelists.org/webpage/oracle-l