Re: Puzzled by 10046 trace
Date: Thu, 31 Mar 2016 19:29:31 -0600
Message-ID: <CAN6wuX15_7M4faMAk22zFWy2XkZ_w7twwwY=pGpmPWWLR59z_g_at_mail.gmail.com>
Have you considered that the wait may be caused by another process performing similar against the same objects.
I love trace data, but could an ash report run at the same timestamp display the missing information to explain the wait scenario?
Kellyn
On Mar 31, 2016 6:41 PM, "Michael Cunningham" <napacunningham_at_gmail.com>
wrote:
> Has anyone ever seen anything like this? I'm trying to figure out why this
> execution of a cursor already in library cache took 2.564 seconds (from FETCH
> #140166221523264:c=5999,e=*2564629*). It appears to be moving along
> fine, then there is a 2.533 second hickup in the middle (see line with: ***
> 2016-03-30 13:34:02.194). Also look at the tim= values for the line after
> and before the *** 2016-03-30 13:34:02.194. If you subtract the tim=4911377763678
> - tim=4911375229962 it = 2533716 which seems to account for 2.533 seconds
> of the 2.564 seconds total. This query would have ran fine if it were not
> for the hickup. I cannot figure out where it came from.
>
> Oracle 12.1.0.2 on RedHat linux.
> It is a join on an IOT and a partitioned table. This trace output is not
> normal. I just traced a session for a long time and this was in there.
> On this server we many connections and there can be 40+ active at a time.
> Any other info that could help, but ask.
>
> Any clues?
> I'm also curious as to why there are no other waits in the trace during
> the missing 2.533 second time frame.
>
> PARSE
> #140166221523264:c=0,e=17,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3652026055,tim=4911375216843
> BINDS #140166221523264:
> Bind#0
> oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
> oacflg=03 fl2=1000000 frm=01 csi=873 siz=72 off=0
> kxsbbbfp=7f7afde3ff28 bln=22 avl=11 flg=05
> value=8826196298240754260
> Bind#1
> oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
> oacflg=03 fl2=1000000 frm=01 csi=873 siz=0 off=24
> kxsbbbfp=7f7afde3ff40 bln=22 avl=06 flg=01
> value=6035036120
> Bind#2
> oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
> oacflg=03 fl2=1000000 frm=01 csi=873 siz=0 off=48
> kxsbbbfp=7f7afde3ff58 bln=22 avl=02 flg=01
> value=25
> EXEC
> #140166221523264:c=0,e=195,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3652026055,tim=4911375217062
> WAIT #140166221523264: nam='SQL*Net message to client' ela= 2 driver
> id=1413697536 #bytes=1 p3=0 obj#=83306 tim=4911375217093
> WAIT #140166221523264: nam='SQL*Net message from client' ela= 701 driver
> id=1413697536 #bytes=1 p3=0 obj#=83306 tim=4911375217836
> WAIT #140166221523264: nam='db file sequential read' ela= 1062 file#=48
> block#=1992249 blocks=1 obj#=93466 tim=4911375219417
> WAIT #140166221523264: nam='db file sequential read' ela= 403 file#=332
> block#=1616664 blocks=1 obj#=93468 tim=4911375220356
> WAIT #140166221523264: nam='db file parallel read' ela= 2355 files=2
> blocks=10 requests=10 obj#=93466 tim=4911375222923
> WAIT #140166221523264: nam='db file sequential read' ela= 1238 file#=322
> block#=1453235 blocks=1 obj#=91729 tim=4911375224267
> WAIT #140166221523264: nam='db file sequential read' ela= 531 file#=364
> block#=1564406 blocks=1 obj#=89686 tim=4911375224883
> WAIT #140166221523264: nam='db file sequential read' ela= 1342 file#=227
> block#=3422655 blocks=1 obj#=85776 tim=4911375226292
> WAIT #140166221523264: nam='db file sequential read' ela= 514 file#=240
> block#=2552750 blocks=1 obj#=91117 tim=4911375226855
> WAIT #140166221523264: nam='db file sequential read' ela= 976 file#=118
> block#=1426853 blocks=1 obj#=91106 tim=4911375227884
> WAIT #140166221523264: nam='db file sequential read' ela= 617 file#=274
> block#=1455038 blocks=1 obj#=81108 tim=4911375228819
> WAIT #140166221523264: nam='db file sequential read' ela= 1022 file#=376
> block#=1905593 blocks=1 obj#=81105 tim=4911375229962
>
> *** 2016-03-30 13:34:02.194
> WAIT #140166221523264: nam='db file sequential read' ela= 901 file#=310
> block#=1904904 blocks=1 obj#=81102 tim=4911377763678
> WAIT #140166221523264: nam='db file sequential read' ela= 959 file#=242
> block#=1355208 blocks=1 obj#=81099 tim=4911377764738
> WAIT #140166221523264: nam='db file sequential read' ela= 1571 file#=247
> block#=1277843 blocks=1 obj#=81075 tim=4911377766380
> WAIT #140166221523264: nam='db file sequential read' ela= 404 file#=251
> block#=1170860 blocks=1 obj#=81051 tim=4911377766865
> WAIT #140166221523264: nam='db file sequential read' ela= 875 file#=332
> block#=1141176 blocks=1 obj#=81027 tim=4911377767817
> WAIT #140166221523264: nam='db file sequential read' ela= 775 file#=57
> block#=3576002 blocks=1 obj#=81003 tim=4911377768668
> WAIT #140166221523264: nam='db file sequential read' ela= 1088 file#=226
> block#=663776 blocks=1 obj#=80979 tim=4911377769822
> WAIT #140166221523264: nam='db file sequential read' ela= 944 file#=220
> block#=3232830 blocks=1 obj#=80955 tim=4911377770825
> WAIT #140166221523264: nam='db file sequential read' ela= 713 file#=112
> block#=2936145 blocks=1 obj#=80931 tim=4911377771587
> WAIT #140166221523264: nam='db file sequential read' ela= 1671 file#=353
> block#=946991 blocks=1 obj#=80907 tim=4911377773327
> WAIT #140166221523264: nam='db file sequential read' ela= 390 file#=247
> block#=733361 blocks=1 obj#=80883 tim=4911377773775
> WAIT #140166221523264: nam='db file sequential read' ela= 394 file#=246
> block#=653716 blocks=1 obj#=80859 tim=4911377774224
> WAIT #140166221523264: nam='db file sequential read' ela= 672 file#=234
> block#=595338 blocks=1 obj#=80835 tim=4911377774951
> WAIT #140166221523264: nam='db file sequential read' ela= 470 file#=238
> block#=120495 blocks=1 obj#=80811 tim=4911377775547
> WAIT #140166221523264: nam='db file sequential read' ela= 1663 file#=122
> block#=403396 blocks=1 obj#=80787 tim=4911377777262
> WAIT #140166221523264: nam='db file sequential read' ela= 1579 file#=243
> block#=243726 blocks=1 obj#=80763 tim=4911377778920
> WAIT #140166221523264: nam='db file sequential read' ela= 449 file#=120
> block#=222551 blocks=1 obj#=80739 tim=4911377779437
> WAIT #140166221523264: nam='db file sequential read' ela= 1366 file#=224
> block#=2762596 blocks=1 obj#=80715 tim=4911377780862
> WAIT #140166221523264: nam='db file sequential read' ela= 435 file#=246
> block#=2827360 blocks=1 obj#=80691 tim=4911377781380
> WAIT #140166221523264: nam='db file sequential read' ela= 905 file#=369
> block#=2740407 blocks=1 obj#=80646 tim=4911377782340
> WAIT #140166221523264: nam='SQL*Net message to client' ela= 3 driver
> id=1413697536 #bytes=1 p3=0 obj#=80646 tim=4911377782416
> FETCH
> #140166221523264:c=5999,e=2564629,p=39,cr=280,cu=0,mis=0,r=13,dep=0,og=1,plh=3652026055,tim=4911377782496
> WAIT #140166221523264: nam='SQL*Net message from client' ela= 9974 driver
> id=1413697536 #bytes=1 p3=0 obj#=80646 tim=4911377792530
> CLOSE #140166221523264:c=0,e=7,dep=0,type=3,tim=4911377792573
>
> --
> Michael Cunningham
>
-- http://www.freelists.org/webpage/oracle-lReceived on Fri Apr 01 2016 - 03:29:31 CEST