RE: Puzzled by 10046 trace

From: Iggy Fernandez <iggy_fernandez_at_hotmail.com>
Date: Thu, 31 Mar 2016 17:47:46 -0700
Message-ID: <BLU179-W342D6521D965314E8716A2EB9A0_at_phx.gbl>

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_at_gmail.com
To: oracle-l_at_freelists.org

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=4911375216843BINDS #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=25EXEC #140166221523264:c=0,e=195,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3652026055,tim=4911375217062WAIT #140166221523264: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=83306 tim=4911375217093WAIT #140166221523264: nam='SQL*Net message from client' ela= 701 driver id=1413697536 #bytes=1 p3=0 obj#=83306 tim=4911375217836WAIT #140166221523264: nam='db file sequential read' ela= 1062 file#=48 block#=1992249 blocks=1 obj#=93466 tim=4911375219417WAIT #140166221523264: nam='db file sequential read' ela= 403 file#=332 block#=1616664 blocks=1 obj#=93468 tim=4911375220356WAIT #140166221523264: nam='db file parallel read' ela= 2355 files=2 blocks=10 requests=10 obj#=93466 tim=4911375222923WAIT #140166221523264: nam='db file sequential read' ela= 1238 file#=322 block#=1453235 blocks=1 obj#=91729 tim=4911375224267WAIT #140166221523264: nam='db file sequential read' ela= 531 file#=364 block#=1564406 blocks=1 obj#=89686 tim=4911375224883WAIT #140166221523264: nam='db file sequential read' ela= 1342 file#=227 block#=3422655 blocks=1 obj#=85776 tim=4911375226292WAIT #140166221523264: nam='db file sequential read' ela= 514 file#=240 block#=2552750 blocks=1 obj#=91117 tim=4911375226855WAIT #140166221523264: nam='db file sequential read' ela= 976 file#=118 block#=1426853 blocks=1 obj#=91106 tim=4911375227884WAIT #140166221523264: nam='db file sequential read' ela= 617 file#=274 block#=1455038 blocks=1 obj#=81108 tim=4911375228819WAIT #140166221523264: nam='db file sequential read' ela= 1022 file#=376 block#=1905593 blocks=1 obj#=81105 tim=4911375229962 *** 2016-03-30 13:34:02.194WAIT #140166221523264: nam='db file sequential read' ela= 901 file#=310 block#=1904904 blocks=1 obj#=81102 tim=4911377763678WAIT #140166221523264: nam='db file sequential read' ela= 959 file#=242 block#=1355208 blocks=1 obj#=81099 tim=4911377764738WAIT #140166221523264: nam='db file sequential read' ela= 1571 file#=247 block#=1277843 blocks=1 obj#=81075 tim=4911377766380WAIT #140166221523264: nam='db file sequential read' ela= 404 file#=251 block#=1170860 blocks=1 obj#=81051 tim=4911377766865WAIT #140166221523264: nam='db file sequential read' ela= 875 file#=332 block#=1141176 blocks=1 obj#=81027 tim=4911377767817WAIT #140166221523264: nam='db file sequential read' ela= 775 file#=57 block#=3576002 blocks=1 obj#=81003 tim=4911377768668WAIT #140166221523264: nam='db file sequential read' ela= 1088 file#=226 block#=663776 blocks=1 obj#=80979 tim=4911377769822WAIT #140166221523264: nam='db file sequential read' ela= 944 file#=220 block#=3232830 blocks=1 obj#=80955 tim=4911377770825WAIT #140166221523264: nam='db file sequential read' ela= 713 file#=112 block#=2936145 blocks=1 obj#=80931 tim=4911377771587WAIT #140166221523264: nam='db file sequential read' ela= 1671 file#=353 block#=946991 blocks=1 obj#=80907 tim=4911377773327WAIT #140166221523264: nam='db file sequential read' ela= 390 file#=247 block#=733361 blocks=1 obj#=80883 tim=4911377773775WAIT #140166221523264: nam='db file sequential read' ela= 394 file#=246 block#=653716 blocks=1 obj#=80859 tim=4911377774224WAIT #140166221523264: nam='db file sequential read' ela= 672 file#=234 block#=595338 blocks=1 obj#=80835 tim=4911377774951WAIT #140166221523264: nam='db file sequential read' ela= 470 file#=238 block#=120495 blocks=1 obj#=80811 tim=4911377775547WAIT #140166221523264: nam='db file sequential read' ela= 1663 file#=122 block#=403396 blocks=1 obj#=80787 tim=4911377777262WAIT #140166221523264: nam='db file sequential read' ela= 1579 file#=243 block#=243726 blocks=1 obj#=80763 tim=4911377778920WAIT #140166221523264: nam='db file sequential read' ela= 449 file#=120 block#=222551 blocks=1 obj#=80739 tim=4911377779437WAIT #140166221523264: nam='db file sequential read' ela= 1366 file#=224 block#=2762596 blocks=1 obj#=80715 tim=4911377780862WAIT #140166221523264: nam='db file sequential read' ela= 435 file#=246 block#=2827360 blocks=1 obj#=80691 tim=4911377781380WAIT #140166221523264: nam='db file sequential read' ela= 905 file#=369 block#=2740407 blocks=1 obj#=80646 tim=4911377782340WAIT #140166221523264: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=80646 tim=4911377782416FETCH #140166221523264:c=5999,e=2564629,p=39,cr=280,cu=0,mis=0,r=13,dep=0,og=1,plh=3652026055,tim=4911377782496WAIT #140166221523264: nam='SQL*Net message from client' ela= 9974 driver id=1413697536 #bytes=1 p3=0 obj#=80646 tim=4911377792530CLOSE #140166221523264:c=0,e=7,dep=0,type=3,tim=4911377792573
--

Michael Cunningham
--

http://www.freelists.org/webpage/oracle-l Received on Fri Apr 01 2016 - 02:47:46 CEST