RE: TKPROF question

From: Jamadagni, Rajendra <Rajendra.Jamadagni_at_espn.com>
Date: Tue, 23 Mar 2004 14:22:12 -0500
Message-ID: <A186CBDC8B1D61438BC50F1A77E91F735B694D@xchgbrsm1.corp.espn.pvt>

Thanks Jonathan,

The time difference between preceding 'tim=' and next 'tim=' as compared to the line in question is about 267 seconds ... so it is sounding like a bug. I am in middle of an itar cretion to find out what the problem is. Because such unreliable numbers can throw off the analysis using tkprof.

block dump shows that it is a leaf block.

Raj

Rajendra dot Jamadagni at nospamespn dot com All Views expressed in this email are strictly personal. select standard_disclaimer from company_requirements; QOTD: Any clod can have facts, having an opinion is an art !

-----Original Message-----

From: oracle-l-bounce_at_freelists.org
[mailto:oracle-l-bounce_at_freelists.org]On Behalf Of Jonathan Lewis Sent: Tuesday, March 23, 2004 1:47 PM
To: oracle-l_at_freelists.org
Subject: Re: TKPROF question

I'd be looking to prove that the figure was a bug. It's 3,288 seconds - and it doesn't tie up with your totals at all.

If you've found the actual line, can you extract a couple of hundred lines either side of it, and check above and below for lines with

tim =
Other lines for the same cursor number (the N of WAIT #N).

tim= is a timestamp in microseconds - do the bracketing tim= lines cater for 3,288,000,000 microseconds elapsed.

Do previous lines for the same cursor - if nearby - make sense ?

If you want to check on the block, you've got the p1, p2 values from the global cache cr request,

alter system dump data file {p1} block {p2} and check for a line which identifies the block as a branch block or a leaf block.

NB If it's the block after the segment header, it's the index root block.

Regards

Jonathan Lewis
http://www.jlcomp.demon.co.uk

The Co-operative Oracle Users' FAQ
http://www.jlcomp.demon.co.uk/faq/ind_faq.html

April 2004 Iceland
June 2004 UK - Optimising Oracle Seminar

Original Message ----- From: "Jamadagni, Rajendra" <Rajendra.Jamadagni_at_espn.com> To: "Oracle List (E-mail)" <oracle-l_at_freelists.org> Sent: Tuesday, March 23, 2004 4:16 PM Subject: RE: TKPROF question

Never mind ... found it now I have to find out why the he11 it waited that long on one block .... and this block is from one index. now how do I find what type of block is this? branch? data?

Why would there be a cr wait of 3288.24 (seconds?/cent-seconds?) if so, it doesn't match with the summary ...

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ------

Parse 6 0.02 0.01 0 0 0 0
Execute 7 0.02 1244.27 503009 11062603 0 4
Fetch 2 0.00 0.00 0 3 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ------

total 15 0.04 1244.29 503009 11062606 0 5

Misses in library cache during parse: 5
Misses in library cache during execute: 1

Elapsed times include waiting on following events:

  Event waited on                             Times   Max. Wait  Total

Waited

Waited ---------- ------------

  SQL*Net message to client                       8        0.00
0.00
  SQL*Net message from client                     8        0.00
0.00
  library cache lock                             27        0.00
0.00
  row cache lock                                  1        0.00
0.00
  log file sync                                   1        0.00

0.00

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ------

Parse 36 0.04 0.06 0 85 0 0
Execute 84 243.62 1244.11 502996 11062248 41821 20188
Fetch 91 0.02 0.14 17 423 0 67
------- ------ -------- ---------- ---------- ---------- ---------- ------

total 211 243.68 1244.32 503013 11062756 41821 20255

Misses in library cache during parse: 24

Elapsed times include waiting on following events:

  Event waited on                             Times   Max. Wait  Total

Waited

Waited ---------- ------------

  library cache lock                             37        0.00
0.00
  row cache lock                                 34        0.00
0.01
  db file sequential read                    492883        0.16
975.74
  global cache cr request                    239402     3288.24
3368.37
  library cache pin                               1        0.00
0.00
  direct path write                            1267        0.00
0.07
  global cache s to x                           155        0.00
0.04
  direct path read                             1582        0.01
0.72
  db file scattered read                         45        0.07
0.38
  global cache open s                             3        0.00
0.00
  global cache open x                            45        0.00

0.01

13 user SQL statements in session.
30 internal SQL statements in session. 43 SQL statements in session.

I am confused ... any help/ponters is greatly appreciated.

Please see the official ORACLE-L FAQ: http://www.orafaq.com

To unsubscribe send email to: oracle-l-request_at_freelists.org put 'unsubscribe' in the subject line.

--
Archives are at http://www.freelists.org/archives/oracle-l/
FAQ is at http://www.freelists.org/help/fom-serve/cache/1.html


-----------------------------------------------------------------

----------------------------------------------------------------

Please see the official ORACLE-L FAQ: http://www.orafaq.com


----------------------------------------------------------------

To unsubscribe send email to:  oracle-l-request_at_freelists.org
put 'unsubscribe' in the subject line.
--
Archives are at http://www.freelists.org/archives/oracle-l/
FAQ is at http://www.freelists.org/help/fom-serve/cache/1.html


-----------------------------------------------------------------

Received on Tue Mar 23 2004 - 14:09:26 CST