Call-Less Cursor

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.

Advertisements

11 Responses to “Call-Less Cursor”

  1. バック グッチ Says:

    。現在、より多く
    のグッチのスタイルはしか
    し、上記の二つは私の独
    自のトップピックですが、見つけることが店の周りにしてくださ
    いあるお好みの
    グッチのバッグの上に最高の価

  2. Darrin Says:

    場合がに関連付けられている春の動向事実は作られて、言ってに、ファッションの滑走路と1つ人間違いなく必要がありますを求めるこれのでそれ。二重監修トートバッグ実際に特集は簡単に削除ショルダーストラップ。考える汎用性をすべて、昼間トートバッグ。

  3. レイバンメガネ Says:

    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.

  4. Austin kayak Says:

    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!

  5. predator Kayak setup Says:

    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.

  6. Jackson Kayaks Says:

    Hello friends, its wonderful piece of writing on the topic of cultureand entirely defined, keep it
    up all the time.

  7. ascend kayak Says:

    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.

  8. www.Youtube.com Says:

    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!

  9. native Kayak Says:

    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.

  10. Http://Www.Youtube.Com/Watch?V=34TjEdU8-WY Says:

    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!!

  11. used dagger kayaks for sale Says:

    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.


Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: