10046 Trace and Oracle Time Machine

From: Jamadagni, Rajendra <Rajendra.Jamadagni_at_espn.com>
Date: Mon, 24 May 2004 08:55:24 -0400
Message-ID: <A186CBDC8B1D61438BC50F1A77E91F73075BDC5B@xchgbrsm1.corp.espn.pvt>

Hi all,

I am currently analyzing couple of trace files (10046^8) and tkprof detected a hidden time machine in Oracle. This is for a simple query
(yes I know how to optimize this one, I have couple of ideas already,
but that's not the point right now) ....=20

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ----------

Parse 1 0.00 0.00 0 0 0 0
Execute 942905 58.99 56.38 0 0 0 0
Fetch 1885764 1767.66 2119363884.22 903 6600178 0 942859
------- ------ -------- ---------- ---------- ---------- ----------

total 2828670 1826.65 2119363940.61 903 6600178 0 942859

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 47 (recursive depth: 1)

Rows Row Source Operation

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

942859 NESTED LOOPS (cr=3D6600178 r=3D903 w=3D0 time=3D90763563 us) 942859 TABLE ACCESS BY INDEX ROWID EPISODE_AVAIL_SUMMARY2 =
(cr=3D4714460

r=3D903 w=3D0 time=3D64274731 us)
942859 INDEX RANGE SCAN PK_EAS_EP_EB_EA_SPOT_TYPE (cr=3D3771597 = r=3D291
w=3D0 time=3D46839360 us)(object id 29510) 942859 TABLE ACCESS BY INDEX ROWID AVAIL_PROCESSING (cr=3D1885718 = r=3D0
w=3D0 time=3D18596514 us)
942859 INDEX UNIQUE SCAN AVAIL_PROCESSING_IDX (cr=3D942859 r=3D0 = w=3D0
time=3D7326352 us)(object id 29118)

Elapsed times include waiting on following events:

  Event waited on                             Times   Max. Wait  Total

Waited

Waited ----------
global cache cr request 491 0.00 0.21 db file sequential read 903 0.05 9.26 global cache s to x 3 0.00 0.00 latch free 11 0.01 0.03

What this tells me that the elapsed time for this query is roughly 67 years ... Before Oracle/Unix were invented ... And yet the whole process which contains this query finishes in roughly 3 hours. 9202, AIX 5.2, 2-node RAC. I have a tar open.=20

Does anyone have any clue as to what the heck is going on? I for one is completely clueless with this output, which I *somehow* think is wrong. Trace file is 3GB, compressed 260MB. Now I am off to write a query for the format "Select 'a_very_large_number from dual;", because OWS is going to ask me for a reproducible test case.

Nice start for a Monday ... Eh? TIA for ideas/jokes/rants/kudos/me-too's

Ps: found a new program for IE addicts, it is a oracle plug-in for internet explorer ... http://www.dbmotive.com, looks cool, but I have no interests in this company BTW.
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 !=20

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 Mon May 24 2004 - 07:52:46 CDT