| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
 |
 | |||
| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
|
| |||
Home -> Community -> Mailing Lists -> Oracle-L -> Re: A mystery & too few clues!
--0-1957747793-966519841=:2451
Content-Type: text/plain; charset=us-ascii
Can you generate the tkprof with explain plans? Based on the 10,000,000 consistent gets, my bet is that something is doing a nested loops join with a table scan on the inner loop. A missing index would cause that.
Another possibility is that the CBO has introduced a cartesian merge because some threshold in the statistics has been crossed. Less likely but possible. Without the explain plans though it's impossible to determine.
Chuck Hamilton
chuck_hamilton_at_qvc.com
chuck_hamilton_at_yahoo.com
Charlie Mengler <charliem_at_mwh.com> wrote:
This problem is on Solaris V2.6 and Oracle V7.3.4
On one of my smaller databases within the last few weeks a couple of the nightly reports went from completing within seconds to taking 10 - 100= minutes to complete. There have been NO changes to the initSID.ora file for months. The system has been rebooted & Oracle get bounced nightly. This is a REAL small database with only a few thousand total records in it & the amount of data has not significantly changed. I did a complete ANALYZE of all the tables & indexes on Sunday.
I monitored the process via V$SES_IO which also reported close to 10,000,000 consistent gets for this single report run. Please NOTE that this DB does NOT have anywhere close to TEN million records in it.
I did enable SQL trace & at the bottom is the output from TKPROF. If/when the raw SQL is run, results are returned immediately. This is being run on a dual CPU SPARC & one CPU gets pegged while this report is "active".
I'd like somebody to explain how, where & why this report goes off & does millions of gets and take 10 - 100+ minutes to complete.
SESSIONID USERID TIMESTAMP LOGOFF$LREAD LOGOFF$PREAD LOGOFF$LWRITE LOGOFF$DEAD LOGOFF$TIME
---------- ------------------------------ ----------------- ------------ ------------ ------------- ----------- -----------------
COMMENT$TEXT
TKPROF: Release 7.3.4.0.0 - Production on Tue Aug 15 07:27:38 2000
Copyright (c) Oracle Corporation 1979, 1996. All rights reserved.
Trace file: ././can_ora_11031.trc
Sort options: default
SELECT NVL(SUM(I.QTY),0) QTY
FROM
MWH.INVQTY I WHERE I.PART = :b1 AND I.LOC = :b2 AND I.TYP LIKE :b3
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 97 0.01 0.01 0 0 0 0
Fetch 98 0.00 0.03 0 291 0 98
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 195 0.01 0.04 0 291 0 98
Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 11 (MWH) (recursive depth: 2)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
0 SORT (AGGREGATE)
0 TABLE ACCESS GOAL: ANALYZED (BY ROWID) OF 'INVQTY'
0 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'P_INVQTY' (UNIQUE)
SELECT NVL(SUM(NVL(D.QTYIN,NVL(D.QTYORD,0))),0) QTY
FROM
MWH.ORDH H,MWH.ORDD D WHERE H.ID = D.ORDHID AND D.PART = :b1 AND D.SHPLOC
= :b2 AND (H.STATUS IN ( 'WPL','PL' ) OR (NVL(:b3,'N') = 'N' AND
H.STATUS = 'SC' ) OR (H.STATUS = 'PE' AND H.SALESLOC NOT IN ( 104,110 )
AND H.ENTRYDT + 2 >= :b4 AND NVL(:b3,'N') = 'N' )) AND H.ID != NVL(:b6,
'?')
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 98 0.01 0.00 0 0 0 0
Fetch 98 0.01 0.01 0 201 0 98
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 196 0.02 0.01 0 201 0 98
Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 11 (MWH) (recursive depth: 2)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
0 SORT (AGGREGATE)
0 NESTED LOOPS
0 TABLE ACCESS GOAL: ANALYZED (BY ROWID) OF 'ORDD'
0 INDEX GOAL: ANALYZED (RANGE SCAN) OF
'I_ORDD_PART_SHPLOC' (NON-UNIQUE)
0 TABLE ACCESS GOAL: ANALYZED (BY ROWID) OF 'ORDH'
0 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'P_ORDH' (UNIQUE)
begin :r:="INVENTORY"."GET_AVAIL_QTY"(:a1,:a2);end;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 97 0.06 0.07 0 3 0 97
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 97 0.06 0.07 0 3 0 97
Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 487 (OPS$KENC) (recursive depth: 1)
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 0 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 0 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 292 0.08 0.08 0 3 0 97
Fetch 196 0.01 0.04 0 492 0 196
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 488 0.09 0.12 0 495 0 293
Misses in library cache during parse: 0
3 user SQL statements in session.
0 internal SQL statements in session.
3 SQL statements in session.
2 statements EXPLAINed in this session.
1 session in tracefile.
3 user SQL statements in trace file.
0 internal SQL statements in trace file.
3 SQL statements in trace file.
3 unique SQL statements in trace file.
2 SQL statements EXPLAINed using schema:
MWH.prof$plan_table
Default table was used.
Table was created.
Table was dropped.
517 lines in trace file.
--
Charlie Mengler Maintenance Warehouse
charliem_at_mwh.com 10641 Scripps Summit Ct
858-831-2229 San Diego, CA 92131
Ready, Fire, Aim; is a sure way to fail as a DBA!
--
Author: Charlie Mengler
INET: charliem_at_mwh.com
Fat City Network Services -- (858) 538-5051 FAX: (858) 538-5051 San Diego, California -- Public Internet access / Mailing Lists
<P>Can you generate the tkprof with explain plans? Based on the 10,000,000 consistent gets, my bet is that something is doing a nested loops join with a table scan on the inner loop. A missing index would cause that. <P>Another possibility is that the CBO has introduced a cartesian merge because some threshold in the statistics has been crossed. Less likely but possible. Without the explain plans though it's impossible to determine. <BLOCKQUOTE style="MARGIN-RIGHT: 0px"> <P>Chuck Hamilton<BR><A href="mailto:chuck_hamilton_at_qvc.com">chuck_hamilton_at_qvc.com</A><BR><A href="mailto:chuck_hamilton_at_yahoo.com">chuck_hamilton_at_yahoo.com</A><BR></P></BLOCKQUOTE> <P> <B><I>Charlie Mengler <charliem_at_mwh.com></I></B> wrote: <BR></P> <BLOCKQUOTE style="BORDER-LEFT: #1010ff 2px solid; MARGIN-LEFT: 5px; PADDING-LEFT: 5px">This problem is on Solaris V2.6 and Oracle V7.3.4<BR><BR>On one of my smaller databases within the last few weeks<BR>a couple of the nightly reports went from completing within<BR>seconds to taking 10 - 100= minutes to complete.<BR>There have been NO changes to the initSID.ora file for months.<BR>The system has been rebooted & Oracle get bounced nightly.<BR>This is a REAL small database with only a few thousand total<BR>records in it & the amount of data has not significantly changed.<BR>I did a complete ANALYZE of all the tables & indexes on Sunday.<BR><BR>I monitored the process via V$SES_IO which also reported close<BR>to 10,000,000 consistent gets for this single report run.<BR>Please NOTE that this DB does NOT have anywhere close to TEN<BR>million records in it.<BR><BR>I did enable SQL trace & at the bottom is the output from TKPROF.<BR>If/when the raw SQL is run, resul! ts are returned immediately.<BR>This is being run on a dual CPU SPARC & one CPU gets pegged<BR>while this report is "active".<BR><BR>I'd like somebody to explain how, where & why this report goes<BR>off & does millions of gets and take 10 - 100+ minutes to complete.<BR><BR>SESSIONID USERID TIMESTAMP LOGOFF$LREAD LOGOFF$PREAD LOGOFF$LWRITE LOGOFF$DEAD LOGOFF$TIME<BR>---------- ------------------------------ ----------------- ------------ ------------ ------------- ----------- -----------------<BR>COMMENT$TEXT<BR>-----------------------------------------------------------------------------------------------------------------------------------<BR>17970411 OPS$KENC 2000-AUG-15:06:59 9951540 0 8 0 2000-AUG-15:07:13<BR>Authenticated by: DATABASE; Client address: (ADDRESS=(PROTOCOL=tcp)(HOST=191.41.100.45)(PORT=46880))<BR><BR><BR><BR><BR>TKPROF: Release 7.3.4.0.0 - Production on Tue Aug 15 07:27:38 2000<BR><BR>Copyright (c) Oracle Corporation 1979, 1996. All rights reserv! ed.<BR><BR>Trace file: ././can_ora_11031.trc<BR>Sort options: default<BR><BR>********************************************************************************<BR>count = number of times OCI procedure was executed<BR>cpu = cpu time in seconds executing <BR>elapsed = elapsed time in seconds executing<BR>disk = number of physical reads of buffers from disk<BR>query = number of buffers gotten for consistent read<BR>current = number of buffers gotten in current mode (usually for update)<BR>rows = number of rows processed by the fetch or execute call<BR>********************************************************************************<BR><BR>SELECT NVL(SUM(I.QTY),0) QTY <BR>FROM<BR>MWH.INVQTY I WHERE I.PART = :b1 AND I.LOC = :b2 AND I.TYP LIKE :b3<BR><BR><BR>call count cpu elapsed disk query current rows<BR>------- ------ -------- ---------- ---------- ---------- ---------- ----------<BR>Parse 0 0.00 0.00 0 0 0 0<BR>Execute 97 0.01 0.01 0 0 0 0<BR>Fetch 98 0.00 0.03 0 291 0 98<BR>-----!Received on Thu Aug 17 2000 - 08:44:01 CDT
-- ------ -------- ---------- ---------- ---------- ---------- ----------<BR>total 195 0.01 0.04 0 291 0 98<BR><BR>Misses in library cache during parse: 0<BR>Optimizer goal: CHOOSE<BR>Parsing user id: 11 (MWH) (recursive depth: 2)<BR><BR>Rows Execution Plan<BR>------- ---------------------------------------------------<BR>0 SELECT STATEMENT GOAL: CHOOSE<BR>0 SORT (AGGREGATE)<BR>0 TABLE ACCESS GOAL: ANALYZED (BY ROWID) OF 'INVQTY'<BR>0 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'P_INVQTY' (UNIQUE)<BR><BR>********************************************************************************<BR><BR>SELECT NVL(SUM(NVL(D.QTYIN,NVL(D.QTYORD,0))),0) QTY <BR>FROM<BR>MWH.ORDH H,MWH.ORDD D WHERE H.ID = D.ORDHID AND D.PART = :b1 AND D.SHPLOC <BR>= :b2 AND (H.STATUS IN ( 'WPL','PL' ) OR (NVL(:b3,'N') = 'N' AND <BR>H.STATUS = 'SC' ) OR (H.STATUS = 'PE' AND H.SALESLOC NOT IN ( 104,110 ) <BR>AND H.ENTRYDT + 2 >= :b4 AND NVL(:b3,'N') = 'N' )) AND H.ID != NVL(:b6,<BR>'?')<BR><BR><BR>call count cpu elap!
sed disk query current rows<BR>------- ------ -------- ---------- ---------- ---------- ---------- ----------<BR>Parse 0 0.00 0.00 0 0 0 0<BR>Execute 98 0.01 0.00 0 0 0 0<BR>Fetch 98 0.01 0.01 0 201 0 98<BR>------- ------ -------- ---------- ---------- ---------- ---------- ----------<BR>total 196 0.02 0.01 0 201 0 98<BR><BR>Misses in library cache during parse: 0<BR>Optimizer goal: CHOOSE<BR>Parsing user id: 11 (MWH) (recursive depth: 2)<BR><BR>Rows Execution Plan<BR>------- ---------------------------------------------------<BR>0 SELECT STATEMENT GOAL: CHOOSE<BR>0 SORT (AGGREGATE)<BR>0 NESTED LOOPS<BR>0 TABLE ACCESS GOAL: ANALYZED (BY ROWID) OF 'ORDD'<BR>0 INDEX GOAL: ANALYZED (RANGE SCAN) OF <BR>'I_ORDD_PART_SHPLOC' (NON-UNIQUE)<BR>0 TABLE ACCESS GOAL: ANALYZED (BY ROWID) OF 'ORDH'<BR>0 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'P_ORDH' (UNIQUE)<BR><BR>********************************************************************************<BR><BR>begin :r:="INVENTORY"."GET_AVAIL_QTY"(:! a1,:a2);end;<BR><BR><BR>call count cpu elapsed disk query current rows<BR>------- ------ -------- ---------- ---------- ---------- ---------- ----------<BR>Parse 0 0.00 0.00 0 0 0 0<BR>Execute 97 0.06 0.07 0 3 0 97<BR>Fetch 0 0.00 0.00 0 0 0 0<BR>------- ------ -------- ---------- ---------- ---------- ---------- ----------<BR>total 97 0.06 0.07 0 3 0 97<BR><BR>Misses in library cache during parse: 0<BR>Optimizer goal: CHOOSE<BR>Parsing user id: 487 (OPS$KENC) (recursive depth: 1)<BR><BR><BR><BR>********************************************************************************<BR><BR>OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS<BR><BR>call count cpu elapsed disk query current rows<BR>------- ------ -------- ---------- ---------- ---------- ---------- ----------<BR>Parse 0 0.00 0.00 0 0 0 0<BR>Execute 0 0.00 0.00 0 0 0 0<BR>Fetch 0 0.00 0.00 0 0 0 0<BR>------- ------ -------- ---------- ---------- ---------- ---------- ----------<BR>total 0 0.00 0.00 0 0 0 0<BR><BR>Misses in l! ibrary cache during parse: 0<BR><BR><BR>OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS<BR><BR>call count cpu elapsed disk query current rows<BR>------- ------ -------- ---------- ---------- ---------- ---------- ----------<BR>Parse 0 0.00 0.00 0 0 0 0<BR>Execute 292 0.08 0.08 0 3 0 97<BR>Fetch 196 0.01 0.04 0 492 0 196<BR>------- ------ -------- ---------- ---------- ---------- ---------- ----------<BR>total 488 0.09 0.12 0 495 0 293<BR><BR>Misses in library cache during parse: 0<BR><BR>3 user SQL statements in session.<BR>0 internal SQL statements in session.<BR>3 SQL statements in session.<BR>2 statements EXPLAINed in this session.<BR>********************************************************************************<BR>Trace file: ././can_ora_11031.trc<BR>Trace file compatibility: 7.03.02<BR>Sort options: default<BR><BR>1 session in tracefile.<BR>3 user SQL statements in trace file.<BR>0 internal SQL statements in trace file.<BR>3 SQL statements in trace file.<BR>3 unique SQL sta! tements in trace file.<BR>2 SQL statements EXPLAINed using schema:<BR>MWH.prof$plan_table<BR>Default table was used.<BR>Table was created.<BR>Table was dropped.<BR>517 lines in trace file.<BR><BR><BR><BR><BR>-- <BR>Charlie Mengler Maintenance Warehouse <BR>charliem_at_mwh.com 10641 Scripps Summit Ct <BR>858-831-2229 San Diego, CA 92131 <BR>Ready, Fire, Aim; is a sure way to fail as a DBA!<BR>-- <BR>Author: Charlie Mengler<BR>INET: charliem_at_mwh.com<BR><BR>Fat City Network Services -- (858) 538-5051 FAX: (858) 538-5051<BR>San Diego, California -- Public Internet access / Mailing Lists<BR>--------------------------------------------------------------------<BR>To REMOVE yourself from this mailing list, send an E-Mail message<BR>to: ListGuru_at_fatcity.com (note EXACT spelling of 'ListGuru') and in<BR>the message BODY, include a line containing: UNSUB ORACLE-L<BR>(or the name of mailing list you want to be removed from). You may<BR>also send the HELP command for other information (like s!
 |
 |