Normally that would simply be indicative of CPU usage - but the reported CPU
usage doesn't match, which suggests two possibilities:
a) Oracle thinks you're on the CPU when you're in the CPU queue
b) Uninstrumented wait
Kelleyn's suggestion for checking v$active_session_history is good, here as we
could expect to see at least two rows in ASH for the gap. If you're too late,
though, and only have dba_hist_active_sess_history to view you might be unlucky
and find the critical 2.5 seconds falling between two of the 10-second
snapshots from ASH.
Despite this you might still be able to see CPU starvation at that point - if
the two snapshots have a time-difference that exceeds (significantly) the 10
second expected gap. (On one occasion I've seen dba_hist showing 12 or 13
seconds between ASH snapshots on a system that was very heavily loaded - ASH
tries to take a snapshot every second, and then the dba_hist picks up every
10th snapshot).
Regards
Jonathan Lewis
http://jonathanlewis.wordpress.com
@jloracle
________________________________
From: oracle-l-bounce@xxxxxxxxxxxxx [oracle-l-bounce@xxxxxxxxxxxxx] on behalf
of Kellyn Pot'Vin-Gorman [dbakevlar@xxxxxxxxx]
Sent: 01 April 2016 02:29
To: Michael Cunningham
Cc: ORACLE-L
Subject: Re: Puzzled by 10046 trace
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@xxxxxxxxx<mailto:napacunningham@xxxxxxxxx>> 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<tel: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
