Many people know that the Tkprof does not report base statistics and times for calls that have recursive calls. This can be handled by other alternative tools. There is one more unfortunate effect to watch out for when doing tuning of a DB that does fair amount of LOB operations. It seems to be more fundamental and much harder to cope with.
Someone was trying to capture performance problem for BLOB loading application. Any method they tried didn’t show good clue to the problem, and they could wonder around it for longer time unless weren’t hinted on certain LOB handling patterns that had been known for some buggy behavior.
But this was just an issue that made me post this other related observation. Here are two excerpts from Tkprof and Statspack reports from database where the case was reproduced.
Tkprof
OVERALL TOTALS FOR
ALL
NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 7 0.02 0.02 4 86 0 0
Execute 9 0.66 1.14 82 2956 5618 8
Fetch 1 0.00 0.00 0 2 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 17 0.68 1.16 86 3044 5618 9
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message from client 100014 54.07 112.26
db file sequential read 1 0.00 0.00
SQL*Net message to client 100013 0.00 0.19
log file sync 10 0.00 0.02
latch: shared pool 11 0.02 0.02
OVERALL TOTALS FOR
ALL
RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 4644 0.94 0.93 0 0 107 0
Execute 11059 6.06 9.85 570 45295 5516 8933
Fetch 23131 0.70 2.23 305 38484 3 28673
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 38834 7.71 13.03 875 83779 5626 37606
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 113211 0.30 324.45
control file sequential read 855 0.03 0.06
direct path write 154743 0.00 0.70
direct path read 99973 0.00 0.64
log file switch completion 111 0.97 65.21
log file switch (checkpoint incomplete) 255 0.97 119.11
latch: shared pool 4 0.00 0.00
latch: checkpoint queue latch 1 0.00 0.00
latch: library cache 1 0.00 0.00
latch: cache buffers chains 1 0.00 0.00
db file scattered read 1 0.00 0.00
Statspack
Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time
----------------------------------------- ------------ ----------- ------ ------
db file sequential read 121,368 373 3 49.4
CPU time 141 18.7
log file switch (checkpoint incomplete) 263 122 463 16.1
log file switch completion 113 66 586 8.8
log file parallel write 3,837 47 12 6.3
-------------------------------------------------------------
Time Model System Stats DB/Inst: TST10203/tst10203 Snaps: 2625-2631
-> Ordered by % of DB time desc, Statistic name
Statistic Time (s) % of DB time
----------------------------------- -------------------- ------------
DB CPU 292.3 40.1
sql execute elapsed time 45.8 6.3
PL/SQL execution elapsed time 32.8 4.5
parse time elapsed 5.4 .7
hard parse elapsed time 5.3 .7
PL/SQL compilation elapsed time 0.1 .0
hard parse (sharing criteria) elaps 0.1 .0
connection management call elapsed 0.0 .0
repeated bind elapsed time 0.0 .0
hard parse (bind mismatch) elapsed 0.0 .0
sequence load elapsed time 0.0 .0
DB time 728.5
background elapsed time 130.7
background cpu time 27.5
-------------------------------------------------------------
Both parts indicate that there was serious activity, like waits on the sequential disk reading and redo log synchronization, CPU utilization, that was not reported in category “sql execute elapsed time” and “PL/SQL execution elapsed time”. There was no statement reported in Tkprof or Statspack that generated this activity, but there was a particular cursor seen all over the 10046 trace that was responsible for some of these missing components.
I kind of was lucky to see it, because the cursor has no associated calls whatsoever, only wait records. Unless there are waits associated with such cursor, there will be no records about it in the Oracle Trace. Another “funny” thing is that this call-less cursor can have recursive calls too. This cursor is created solely to write and read LOB content.
So, here are few words of caution for those who do performance troubleshooting using raw trace files, Statspack or ASH/AWR reports. Tkprof or other tools that would try to calculate CPU, Elapsed Time or Wait statistics and build hierarchy of calls of sessions containing LOB operations will likely produce incorrect results from slightly wrong to misleading. This is because calls contain major information that allows traversing call hierarchy and calculating base statistics and timing figures. The “missing” calls might cause whole call hierarchy tree to break. For the same reason Statspack reports may show resource consumption without any visible consumer.
One more thing worth mentioning. If LOB operations are wrapped into code that uses calls to communicate with the database (i.e. PL/SQL anonymous blocks or procedures), then the resources consumed by the LOB operations inside that code will be assigned to these calls.
April 18, 2013 at 12:27 pm
。現在、より多く
のグッチのスタイルはしか
し、上記の二つは私の独
自のトップピックですが、見つけることが店の周りにしてくださ
いあるお好みの
グッチのバッグの上に最高の価
格
June 17, 2013 at 4:08 pm
場合がに関連付けられている春の動向事実は作られて、言ってに、ファッションの滑走路と1つ人間違いなく必要がありますを求めるこれのでそれ。二重監修トートバッグ実際に特集は簡単に削除ショルダーストラップ。考える汎用性をすべて、昼間トートバッグ。
July 8, 2013 at 3:21 am
Kincaid, Splendid, along with quite a few other leading manufacturers.
The sticker consists of manufacturer specifics, frame type, serial amount, and product number.
As substantially as I appreciated the initial ‘Men in Black,’ I thought the sequel
was horrible. What ever it is, you can flatter pleasing much and whittle.
September 21, 2014 at 3:35 am
fantastic submit, very informative. I wonder why the other experts of this sector do
not realize this. You should proceed your writing. I’m sure, you have a
huge readers’ base already!
September 21, 2014 at 3:35 am
May I simply just say what a relief to discover somebody that really knows what
they are talking about on the web. You definitely understand how to bring an issue to light and make it important.
More and more people need to look at this and understand this side of the story.
I was surprised you’re not more popular since you surely have the
gift.
September 21, 2014 at 3:46 am
Hello friends, its wonderful piece of writing on the topic of cultureand entirely defined, keep it
up all the time.
September 21, 2014 at 4:28 am
Thank you for every other wonderful article. Where else may just anyone get that type of information in such a
perfect approach of writing? I’ve a presentation subsequent week, and I’m on the look for such information.
September 21, 2014 at 5:41 am
Thanks for your personal marvelous posting!
I truly enjoyed reading it, you could be a great author.
I will make certain to bookmark your blog and definitely will come back later on. I want to encourage yourself to continue your great work, have a nice morning!
September 21, 2014 at 7:18 am
If some one needs to be updated with newest technologies then he must be go to see this web site and be up to date all the time.
September 21, 2014 at 8:13 am
Good site you’ve got here.. It’s hard to find good quality writing like yours nowadays.
I truly appreciate individuals like you! Take care!!
September 21, 2014 at 8:22 am
whoah this blog is fantastic i love reading your articles.
Stay up the good work! You recognize, a lot of people are
looking round for this info, you can aid them greatly.