All those are possible and wait on I/O at the storage subsystem.
I had one of these occur on a Exadata recently where the wait time missing
was about 16 hours.
Matthew Parker
Chief Technologist
Dimensional DBA
425-891-7934 (cell)
D&B 047931344
CAGE 7J5S7
<mailto:Dimensional.dba@xxxxxxxxxxx> Dimensional.dba@xxxxxxxxxxx
<http://www.linkedin.com/pub/matthew-parker/6/51b/944/> View Matthew
Parker's profile on LinkedIn
<http://www.dimensionaldba.com/> www.dimensionaldba.com
From: oracle-l-bounce@xxxxxxxxxxxxx [mailto:oracle-l-bounce@xxxxxxxxxxxxx]
On Behalf Of Iggy Fernandez
Sent: Thursday, March 31, 2016 5:48 PM
To: napacunningham@xxxxxxxxx; oracle-l@freelists org
Subject: RE: Puzzled by 10046 trace
Slowdown caused by writing to the trace file (instead of doing actual work)
Resource Manager scheduling?
Virtual Machine starvation?
100% CPU?
Swapping?
_____
Date: Thu, 31 Mar 2016 17:41:14 -0700
Subject: Puzzled by 10046 trace
From: napacunningham@xxxxxxxxx
To: oracle-l@xxxxxxxxxxxxx
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
