We have some PL/SQL that is running many sql statements, and taking an awfully long time to complete. (It’s Oracle code, btw, in E-Business, not custom). The problem seems to be a couple of the statements, (run thousands of times each) where the execution time per statement starts off fast but deteriorates over time.
I have traced the process, and investigated one of the statements in the .trc file. It shows that the number of Consistent Reads is increasing by approx. 6 for each FETCH. It starts off at Fetch #1 with cr=239. By fetch #1000, cr=5898, and fetch #10000 is cr=57341, and so on. It continues like that until fetch #23596, where cr=137500. The next fetch, #23597, Consistent Reads jumps to a massive cr=4295104797.
Also, the EXEC phase of each execution shows cr=0 all the way up to exec# 23597, when it jumps to 4294967296, and stays at that level to the end. This must be related to the big jump in FETCH CR’s at the same point
It’s a relatively simple statement, with one bind variable, and indexes are well used. If I take any value of the bind variable for CASH_RECEIPT_ID, and run the query in SQLPlus with autotrace, it reports just 15 Consistent Reads. How do I figure out what’s going on with the growing Fetch reads? The DB is 11.2.0.4.
SELECT CR.DEPOSIT_DATE
, RM.MATURITY_DATE_RULE_CODE
, PS.DUE_DATE
, PS.AMOUNT_APPLIED
, CR.ORG_ID
, RC.CREATION_STATUS
FROM AR_CASH_RECEIPTS CR
, AR_RECEIPT_METHODS RM
, AR_RECEIPT_CLASSES RC
, AR_PAYMENT_SCHEDULES PS
WHERE CR.CASH_RECEIPT_ID = :B1
AND CR.RECEIPT_METHOD_ID = RM.RECEIPT_METHOD_ID
AND RM.RECEIPT_CLASS_ID = RC.RECEIPT_CLASS_ID
AND CR.CASH_RECEIPT_ID = PS.CASH_RECEIPT_ID
From the tkprof filecall count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 25337 1.57 1.96 0 0 0 0
Fetch 25337 4540.76 5850.78 565 1936111336 0 25337
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 50675 4542.33 5852.75 565 1936111336 0 25337
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 173 (APPS) (recursive depth: 1)
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 NESTED LOOPS (cr=239 pr=0 pw=0 time=2739 us cost=8 size=67 card=1)
1 1 1 NESTED LOOPS (cr=8 pr=0 pw=0 time=75 us cost=5 size=47 card=1)
1 1 1 NESTED LOOPS (cr=6 pr=0 pw=0 time=63 us cost=4 size=34 card=1)
1 1 1 TABLE ACCESS BY INDEX ROWID AR_CASH_RECEIPTS_ALL (cr=4 pr=0 pw=0 time=46 us cost=3 size=23 card=1)
1 1 1 INDEX UNIQUE SCAN AR_CASH_RECEIPTS_U1 (cr=3 pr=0 pw=0 time=27 us cost=2 size=0 card=1)(object id 28821)
1 1 1 TABLE ACCESS BY INDEX ROWID AR_RECEIPT_METHODS (cr=2 pr=0 pw=0 time=13 us cost=1 size=11 card=1)
1 1 1 INDEX UNIQUE SCAN AR_RECEIPT_METHODS_U1 (cr=1 pr=0 pw=0 time=8 us cost=0 size=0 card=1)(object id 28962)
1 1 1 TABLE ACCESS BY INDEX ROWID AR_RECEIPT_CLASSES (cr=2 pr=0 pw=0 time=9 us cost=1 size=13 card=1)
1 1 1 INDEX UNIQUE SCAN AR_RECEIPT_CLASSES_U1 (cr=1 pr=0 pw=0 time=4 us cost=0 size=0 card=1)(object id 28955)
1 1 1 TABLE ACCESS BY INDEX ROWID AR_PAYMENT_SCHEDULES_ALL (cr=231 pr=0 pw=0 time=2660 us cost=3 size=20 card=1)
1 1 1 INDEX RANGE SCAN AR_PAYMENT_SCHEDULES_U2 (cr=217 pr=0 pw=0 time=2529 us cost=2 size=0 card=1)(object id 10103816)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT MODE: ALL_ROWS
1 FILTER
1 NESTED LOOPS
1 NESTED LOOPS
1 NESTED LOOPS
1 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID) OF 'AR_CASH_RECEIPTS_ALL' (TABLE)
1 INDEX MODE: ANALYZED (UNIQUE SCAN) OF 'AR_CASH_RECEIPTS_U1' (INDEX (UNIQUE))
1 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID) OF 'AR_RECEIPT_METHODS' (TABLE)
1 INDEX MODE: ANALYZED (UNIQUE SCAN) OF 'AR_RECEIPT_METHODS_U1' (INDEX (UNIQUE))
1 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID) OF 'AR_RECEIPT_CLASSES' (TABLE)
1 INDEX MODE: ANALYZED (UNIQUE SCAN) OF 'AR_RECEIPT_CLASSES_U1' (INDEX (UNIQUE))
1 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID) OF 'AR_PAYMENT_SCHEDULES_ALL' (TABLE)
0 INDEX MODE: ANALYZED (RANGE SCAN) OF 'AR_PAYMENT_SCHEDULES_U2' (INDEX (UNIQUE))
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
latch free 3576 0.05 18.73
buffer busy waits 61 0.01 0.12
latch: cache buffers chains 381 0.01 1.83
latch: undo global data 43 0.01 0.24
db file sequential read 565 0.01 2.52
log file switch (private strand flush incomplete)
6 0.13 0.31
latch: row cache objects 1 0.00 0.00
latch: object queue header operation 2 0.00 0.00
cursor: pin S 1 0.01 0.01
wait list latch free 1 0.01 0.01
********************************************************************************
Selected lines from the .trc file(# 1) FETCH #140170374123664:c=1000, e=2747, p=0,cr=239, cu=0,mis=0,r=1,dep=1,og=1,plh=2856441658,tim=1525433717686202
(# 1000) FETCH #140170374123664:c=13997, e=22312, p=0,cr=5898, cu=0,mis=0,r=1,dep=1,og=1,plh=2856441658,tim=1525433845074689
(# 10000) FETCH #140170374123664:c=135979,e=239836,p=0,cr=57341, cu=0,mis=0,r=1,dep=1,og=1,plh=2856441658,tim=1525435840653235
(# 23596) FETCH #140170374123664:c=325951,e=517110,p=0,cr=137500, cu=0,mis=0,r=1,dep=1,og=1,plh=2856441658,tim=1525441928606080
(# 23597) FETCH #140170374123664:c=324950,e=524567,p=0,cr=4295104797,cu=0,mis=0,r=1,dep=1,og=1,plh=2856441658,tim=1525441929257893
(# 25337) FETCH #140170374123664:c=344948,e=345357,p=0,cr=4295114803,cu=0,mis=0,r=1,dep=1,og=1,plh=2856441658,tim=1525442991902742
I'm betting you've got heavy DML going on those tables, and we are working very hard to give you consistent results. For example
SQL> create table t as select 1 x from dual;
Table created.
SQL> conn mcdonac/alicat1
Connected.
SQL> variable r1 refcursor
SQL> variable r2 refcursor
SQL>
SQL> exec open :r1 for select * from t;
PL/SQL procedure successfully completed.
SQL> exec open :r2 for select * from t;
PL/SQL procedure successfully completed.
SQL>
SQL> select s.name, st.value
2 from v$statname s, v$mystat st
3 where st.statistic# = s.statistic#
4 and s.name in ('consistent gets','data blocks consistent reads - undo records applied');
NAME VALUE
-------------------------------------------------- ----------
consistent gets 58
data blocks consistent reads - undo records applied 0
2 rows selected.
SQL>
SQL> print r1
X
----------
1
1 row selected.
SQL>
SQL> select s.name, st.value
2 from v$statname s, v$mystat st
3 where st.statistic# = s.statistic#
4 and s.name in ('consistent gets','data blocks consistent reads - undo records applied');
NAME VALUE
-------------------------------------------------- ----------
consistent gets 61
data blocks consistent reads - undo records applied 0
2 rows selected.
So I opened two cursors (r1 and r2) to query one row table "T".
When I "print" r1 (which means actually do the fetching), you can see I took 61-58 = 3 consistent gets.
Which is what you would expect, because its 1 row table, so minimal work.
Now I do the following:
SQL> begin
2 for i in 1 .. 50000 loop
3 update t set x = x + 1 ;
4 commit;
5 end loop;
6 end;
7 /
PL/SQL procedure successfully completed.
I've just 50,000 transactions on the table. But don't forget, I *opened* refcursor R2 *before* I did those transactions, so when I print R2 ,I need to see the data as it was *before* them. All of those changes need to be undone.
SQL> print r2
X
----------
1
1 row selected.
SQL>
SQL> select s.name, st.value
2 from v$statname s, v$mystat st
3 where st.statistic# = s.statistic#
4 and s.name in ('consistent gets','data blocks consistent reads - undo records applied');
NAME VALUE
-------------------------------------------------- ----------
consistent gets 50067
data blocks consistent reads - undo records applied 50003
And there you go ... 50,067 consistent gets just to get ONE row. And you see that 50,003 of those were undo-ing work that has been applied to that block since the cursor was opened.