Re: [Fwd: Re: 10046 trace - unaccounted for time]
- From: Riyaj Shamsudeen <riyaj.shamsudeen@xxxxxxxxx>
- To: kmoore@xxxxxxxxxxxx
- Date: Wed, 06 Aug 2008 17:37:33 -0500
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
--
//www.freelists.org/webpage/oracle-l
Other related posts:
