sreekanth -- Thanks for the question regarding "Permance issues after upgrading to RAC", version 10.2.0.4
Submitted on 15-Jul-2009 12:46 Central time zone
Last updated 24-Jul-2009 9:41
You Asked
tom,
when i submitted this i got a page cannot be displayed error. so i am submitting again.
we are running oracle applications 11.5.10 on linux and we upgraded to RAC last week and we are seeing some formance issues, but these are wierd.
issue no.1
we have query as part of concurrent program running slow after the upgrade. so we started tracing this. funny thing is when we enable trace the query goes fast. Initially i did not believe it but after testing at least 20 times, this query does run fast(35 min) with trace on. with no trace this runs for more than 8 hours. why does this happen.
Issue no.2
we have a query which runs fast(couple seconds) sometimes but some times it runs veryslow(8 min).
Here is the raw trace file when it run fast.
=====================
PARSING IN CURSOR #55 len=92 dep=1 uid=190 oct=3 lid=190 tim=1218427241877861 hv=2311769102 ad='36df1018'
SELECT 'X' FROM SF_PENDING_FUNCTION_QUEUES WHERE USER_ID = :b1 AND FUNCTION_ID = :b2
END OF STMT
PARSE #55:c=1000,e=245,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=1218427241877859
WAIT #55: nam='library cache lock' ela= 259 handle address=5314638672 lock address=4501402448 100*mode+namespace=301 obj#=76287 tim=1218427241878224
=====================
here is the raw trace file when runs slow,
=====================
PARSING IN CURSOR #45 len=92 dep=1 uid=190 oct=3 lid=190 tim=1218427212913160 hv=2311769102 ad='24eb2058'
SELECT 'X' FROM SF_PENDING_FUNCTION_QUEUES WHERE USER_ID = :b1 AND FUNCTION_ID = :b2
END OF STMT
EXEC #45:c=0,e=144,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1218427212913157
WAIT #45: nam='db file sequential read' ela= 7159 file#=274 block#=354635 blocks=1 obj#=76214 tim=1218427212922020
WAIT #45: nam='db file scattered read' ela= 4592 file#=274 block#=354637 blocks=5 obj#=76214 tim=1218427212927127
WAIT #45: nam='db file scattered read' ela= 1677 file#=274 block#=354643 blocks=3 obj#=76214 tim=1218427212929944
WAIT #45: nam='db file sequential read' ela= 8102 file#=274 block#=354648 blocks=1 obj#=76214 tim=1218427212938167
WAIT #45: nam='db file sequential read' ela= 6464 file#=277 block#=161196 blocks=1 obj#=76137 tim=1218427212945783
WAIT #45: nam='db file sequential read' ela= 7303 file#=407 block#=150140 blocks=1 obj#=76137 tim=1218427212953151
WAIT #45: nam='db file sequential read' ela= 4606 file#=275 block#=150272 blocks=1 obj#=76137 tim=1218427212957854
WAIT #45: nam='db file sequential read' ela= 6905 file#=407 block#=847377 blocks=1 obj#=76137 tim=1218427212964872
WAIT #45: nam='db file sequential read' ela= 315 file#=275 block#=1025848 blocks=1 obj#=76137 tim=1218427212965283
WAIT #45: nam='db file sequential read' ela= 6735 file#=276 block#=653607 blocks=1 obj#=76137 tim=1218427212972072
WAIT #45: nam='db file sequential read' ela= 6457 file#=275 block#=960639 blocks=1 obj#=76137 tim=1218427212978587
WAIT #45: nam='db file sequential read' ela= 5643 file#=275 block#=1027705 blocks=1 obj#=76137 tim=1218427212984276
WAIT #45: nam='db file sequential read' ela= 6071 file#=276 block#=526955 blocks=1 obj#=76137 tim=1218427212990391
WAIT #45: nam='db file sequential read' ela= 4309 file#=275 block#=994522 blocks=1 obj#=76137 tim=1218427212994740
WAIT #45: nam='db file sequential read' ela= 4215 file#=276 block#=657452 blocks=1 obj#=76137 tim=1218427212999033
WAIT #45: nam='db file sequential read' ela= 4867 file#=276 block#=657450 blocks=1 obj#=76137 tim=1218427213003972
WAIT #45: nam='db file sequential read' ela= 6942 file#=276 block#=657461 blocks=1 obj#=76137 tim=1218427213010955
WAIT #45: nam='db file sequential read' ela= 4675 file#=275 block#=1035780 blocks=1 obj#=76137 tim=1218427213015678
WAIT #45: nam='db file sequential read' ela= 7411 file#=275 block#=1037318 blocks=1 obj#=76137 tim=1218427213023145
WAIT #45: nam='db file sequential read' ela= 7265 file#=275 block#=982304 blocks=1 obj#=76137 tim=1218427213030495
WAIT #45: nam='db file sequential read' ela= 5390 file#=275 block#=1041076 blocks=1 obj#=76137 tim=1218427213035940
WAIT #45: nam='db file sequential read' ela= 11728 file#=276 block#=668686 blocks=1 obj#=76137 tim=1218427213047749
WAIT #45: nam='db file sequential read' ela= 7359 file#=276 block#=671065 blocks=1 obj#=76137 tim=1218427213055189
WAIT #45: nam='db file sequential read' ela= 15064 file#=276 block#=570148 blocks=1 obj#=76137 tim=1218427213070321
WAIT #45: nam='db file sequential read' ela= 7766 file#=276 block#=568359 blocks=1 obj#=76137 tim=1218427213078171
WAIT #45: nam='db file sequential read' ela= 6905 file#=276 block#=570141 blocks=1 obj#=76137 tim=1218427213085156
WAIT #45: nam='db file sequential read' ela= 5088 file#=275 block#=987753 blocks=1 obj#=76137 tim=1218427213094930
WAIT #45: nam='db file sequential read' ela= 6399 file#=276 block#=568357 blocks=1 obj#=76137 tim=1218427213101400
WAIT #45: nam='db file sequential read' ela= 8010 file#=275 block#=987765 blocks=1 obj#=76137 tim=1218427213109456
WAIT
this goes like this at least 10 pages.
thanks for your help.
sreekanth.g
and we said...
See how to tune with sql_trace=true :)
http://tkyte.blogspot.com/2007/09/tuning-with-sqltracetrue.html http://tkyte.blogspot.com/2007/09/sqltracetrue-part-two.html
Thanks
July 16, 2009 - 3pm Central time zone
Reviewer: sreekanth gadhraju from tampa
Thanks
Deductions from the trace file
July 19, 2009 - 5am Central time zone
Reviewer: Gary from Sydney, Aus
Just going from that bit of trace file for issue 2, are these fair deductions.
On the slow run, there are two object ids (76214 and 76137) and the scattered reads on the former
indicate it is an index, and the latter would be the table.
That suggests that either USER_ID or FUNCTION_ID is indexed. Since a literal is selected, the only
reason to visit the table would be to check the other column and the 76214 index is on only one of
those columns.
Furthermore, when it does hit the table, it is hitting files 277, 407, then lots of switching
between files 275 and 276. If the indexed column was the only column in the index, then the entries
would be in ROWID order in the index (for a given value of that indexed column) so wouldn't switch
back and forth between those files. Therefore the column is the leading column of the index, but it
is not the only column of the index.
Beyond that, it would be hypothesising (eg a skew in the column data so that when it checking for a
common value for the indexed column but a rare value for the unindexed one, it just has a lot of
rows to plough through).
PS. I'm not suggesting not doing further trace analysis. Just treating this as an exercise in what
can be deduced from a trace file Followup July 24, 2009 - 9am Central time zone:
well, the traces are completely incomplete - the first "fast one" doesn't show the fetch call at all, we don't see a plan, no stat records, nothing useful really.
I think there are two plans, and when they turn on sql trace to test - they got a new hard parse with bind variables that resulted in their "fast plan" (but only fast for that set of bind inputs).
They need to investigate the plans - but yes, I think sometimes it is picking an index and sometimes not and one of the plans is in general "bad"