RE: Puzzled by 10046 trace

From: Chitale, Hemant K <Hemant-K.Chitale_at_sc.com>
Date: Fri, 1 Apr 2016 03:25:59 +0000
Message-ID: <2FE2AA1C5F8DEC478F58DF8DD32BA63716BFDD_at_HKWPIPXMB03C.zone1.scb.net>

Although we might think that trace files report *everything*, it isn’t true. Sometimes a wait event just doesn’t get reported. It could be due to lack of CPU or some resource constraint. IMHO, Oracle doesn’t give a very high priority to writing everything into the trace file (and rightly so, because tracing itself is an overhead).

Hemant K Chitale

From: oracle-l-bounce_at_freelists.org [mailto:oracle-l-bounce_at_freelists.org] On Behalf Of Michael Cunningham Sent: Friday, April 01, 2016 8:41 AM
To: oracle-l_at_freelists org
Subject: Puzzled by 10046 trace

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

This email and any attachments are confidential and may also be privileged. If you are not the intended recipient, please delete all copies and notify the sender immediately. You may wish to refer to the incorporation details of Standard Chartered PLC, Standard Chartered Bank and their subsidiaries at https://www.sc.com/en/incorporation-details.html

--

http://www.freelists.org/webpage/oracle-l Received on Fri Apr 01 2016 - 05:25:59 CEST