Re: Oracle Locator performance issue (10046 trace data)

  • From: Chris Stephens <cstephens16@xxxxxxxxx>
  • To: Stefan Koehler <contact@xxxxxxxx>
  • Date: Fri, 25 Oct 2019 08:20:24 -0500

"Might it be possible..."

absolutely. i was given this trace data and asked to take a look at it. it
didn't occur to me until after i sent the initial email that i was missing
all the slave trace files. if i get time this afternoon, i'll ask for those
as well to see what additional info is there. for now, the developer
realized he could filter the vast majority of rows out prior to doing any
locator stuff.

Thanks for all the responses!

JL: sorry about not providing formatted exec plan. I'll do that next time!


On Fri, Oct 25, 2019 at 6:30 AM Stefan Koehler <contact@xxxxxxxx> wrote:

Hello Chris,

Trace data shows a single fetch call accounts for vast majority of
response time. I don't know if this is due to lack of instrumentation w/
locator or something else.

Might it be possible that you have traced the PX COORDINATOR only? You
have a PQ and so it is very like that the elapsed time of "FETCH
#140556737969632:c=70530,e=580279740" is spent in its slaves :)

I think the best way would be to run the SQL as unique statement with
rowsource statistics enabled (e.g. gather_plan_statistics,
statistics_level, _rowsource_execution_statistics) and then use DBMS_XPLAN
without last option. Afterwards you can go deeper with traces if still
needed :-)

Best Regards
Stefan Koehler

Independent Oracle performance consultant and researcher
Website: http://www.soocs.de
Twitter: @OracleSK

Chris Stephens <cstephens16@xxxxxxxxx> hat am 24. Oktober 2019 um 21:01
geschrieben:

We are starting to mess with Oracle Locator some and immediately hit
performance issue. Trace data shows a single fetch call accounts for vast
majority of response time. I don't know if this is due to lack of
instrumentation w/ locator or something else. Does anyone have experience
w/ this kind of this that might be able to provide some insight?
Oracle 12.2
*** 2019-10-24T12:57:20.329694-05:00
FETCH
#140556737969632:c=70530,e=580279740,p=0,cr=0,cu=0,mis=0,r=20,dep=0,og=1,plh=2353454263,tim=10624057091673

STAT #140556737969632 id=1 cnt=20 pid=0 pos=1 obj=0 op='COUNT STOPKEY
(cr=0 pr=0 pw=0 str=1 time=580294149 us)'
STAT #140556737969632 id=2 cnt=20 pid=1 pos=1 obj=0 op='PX COORDINATOR
 (cr=0 pr=0 pw=0 str=1 time=580294109 us)'
STAT #140556737969632 id=3 cnt=0 pid=2 pos=1 obj=0 op='PX SEND QC
(ORDER) :TQ10001 (cr=0 pr=0 pw=0 str=0 time=0 us cost=24196 size=64309407
card=691499)'
STAT #140556737969632 id=4 cnt=0 pid=3 pos=1 obj=0 op='VIEW  (cr=0 pr=0
pw=0 str=0 time=0 us cost=24196 size=64309407 card=691499)'
STAT #140556737969632 id=5 cnt=0 pid=4 pos=1 obj=0 op='SORT ORDER BY
STOPKEY (cr=0 pr=0 pw=0 str=0 time=0 us cost=24196 size=43564437
card=691499)'
STAT #140556737969632 id=6 cnt=0 pid=5 pos=1 obj=0 op='PX RECEIVE  (cr=0
pr=0 pw=0 str=0 time=0 us cost=13731 size=43564437 card=691499)'
STAT #140556737969632 id=7 cnt=0 pid=6 pos=1 obj=0 op='PX SEND RANGE
:TQ10000 (cr=0 pr=0 pw=0 str=0 time=0 us cost=13731 size=43564437
card=691499)'
STAT #140556737969632 id=8 cnt=0 pid=7 pos=1 obj=0 op='PX PARTITION
RANGE ALL PARTITION: 1 16 (cr=0 pr=0 pw=0 str=0 time=0 us cost=13731
size=43564437 card=691499)'
STAT #140556737969632 id=9 cnt=0 pid=8 pos=1 obj=0 op='SORT ORDER BY
STOPKEY (cr=0 pr=0 pw=0 str=0 time=0 us)'
STAT #140556737969632 id=10 cnt=0 pid=9 pos=1 obj=714991 op='TABLE
ACCESS BY LOCAL INDEX ROWID Y6A1_LOCATOR PARTITION: 1 16 (cr=0 pr=0 pw=0
str=0 time=0 us cost=13731 size=43564437 card=691499)'
STAT #140556737969632 id=11 cnt=0 pid=10 pos=1 obj=715087 op='DOMAIN
INDEX (SEL: 0.100000 %) Y6A1_LOCATOR_GEO_BTX (cr=0 pr=0 pw=0 str=0 time=0
us cost=5 size=0 card=0)'
EXEC
#140556737964464:c=87,e=87,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=0,tim=10624057093221

XCTEND rlbk=0, rd_only=1, tim=10624057093262

Other related posts: