Skip to Main Content
  • Questions
  • Why might Consistent Reads be increasing with every iteration of a select cursor being run by PL/SQL?

Breadcrumb

May 4th

Question and Answer

Connor McDonald

Thanks for the question, Allan.

Asked: May 24, 2018 - 12:46 pm UTC

Last updated: May 29, 2018 - 1:53 am UTC

Version: 11.2.0.4

Viewed 1000+ times

You Asked

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 file

call     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


and Connor said...

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.

Rating

  (2 ratings)

Is this answer out of date? If it is, please let us know via a Comment

Comments

Any suggestions

Gh, May 28, 2018 - 8:21 am UTC

Very Good explanation and demo.
Tough how could workaround or minimize impact without changing the events chronology.
For example by changing the physical attributes of the table? Partitioning ? What could be done to make it more performing side?
Connor McDonald
May 29, 2018 - 1:53 am UTC

The key things here are

- the time between opening a cursor and fetching from it.
- the number of blocks you need to undo

If you can limit those, then you're less impacted.

A perfect and simple explanation, in rapid time.

Allan Webster, May 30, 2018 - 9:22 am UTC

You are correct, there is very high DML going on in other sessions, which we hadn't considered before. This qry is part of an EBS Concurrent Request that spawns a user definable number of child requests to do the work. We were spawning 7. They are all doing the same set of SQL for different records.

The request also uses a user definable commit parameter, which we clearly have set way too high (25000). That might be OK for running with a single child process, but is very bad when running with multiple ones.

Thank you very much.


More to Explore

Administration

Need more information on Administration? Check out the Administrators guide for the Oracle Database