| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
 |
 | |||
| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
|
| |||
Home -> Community -> Mailing Lists -> Oracle-L -> A mystery & too few clues!
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
17970411 OPS$KENC 2000-AUG-15:06:59 9951540 0 8 0 2000-AUG-15:07:13Authenticated by: DATABASE; Client address: (ADDRESS=(PROTOCOL=tcp)(HOST=191.41.100.45)(PORT=46880))
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
count = number of times OCI procedure was executed cpu = cpu time in seconds executing elapsed = elapsed time in seconds executing disk = number of physical reads of buffers from disk query = number of buffers gotten for consistent read current = number of buffers gotten in current mode (usually for update) rows = number of rows processed by the fetch or execute call ********************************************************************************
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
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
Received on Tue Aug 15 2000 - 11:13:38 CDT
 |
 |