Skip to Main Content
  • Questions

  • The most peculiar Oracle situation in my career- Oracle changes how it records a block read from direct read to not recording it in an I/O wait event at all

Breadcrumb

Question and Answer

Connor McDonald

Thanks for the question, John.

Asked: May 07, 2021 - 1:19 pm UTC

Last updated: May 12, 2021 - 7:07 am UTC

Version: 19c

Viewed 1000+ times

You Asked

Greetings,

I have this extremely perplexing situation where Oracle changes how it records a block read. Last week it wasn't COUNTING block reads at all in an I/O wait event; this week it started to add it to the “direct read” wait event. This is occurring in our production environment; however, I was able to reproduce the situation in our test environment with test data.

I used all_source view to create two test tables until I reached 1.2 million for table 1 and 4 million for table 2:
Table1 ( 1.2 Mil records) create table table1 as select * from dba_source where rownum;
Table2 ( 4 Mil records ) create table table2 as select * from dba_source;
create index t1_pk on table1(owner);
create index t2_pk on table2(owner, line);
exec dbms_stats.gather_schema_stats('JOHN');

Then I ran this select statement 120 times:

select count(*) from Table1 where line=1 and owner in (select Table2.owner from Table2 where Table2.owner=Table1.owner) order by owner;


In some cases Oracle 19c records the I/O in "direct path read" wait events and in other cases, it doesn't seem to report in any I/O wait event. That is soooo odd.


TEST CASE 1: IOStats summary doesn't record I/O nor does it in a wait event:

Top 10 Foreground Events by Total Wait Time
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                           Total Wait       Avg   % DB Wait
Event                                Waits Time (sec)      Wait   time Class
------------------------------ ----------- ---------- --------- ------ --------
DB CPU                                           20.2             99.6
PGA memory operation                 2,524         .1   20.27us     .3 Other
Disk file operations I/O               520          0   59.49us     .2 User I/O
db file sequential read                211          0   12.33us     .0 User I/O
Parameter File I/O                       8          0  257.00us     .0 User I/O
enq: RO - fast object reuse              2          0  784.50us     .0 Applicat
control file sequential read           209          0    5.32us     .0 System I
log file sync                            1          0     .95ms     .0 Commit
SQL*Net message to client              546          0    1.53us     .0 Network
SQL*Net more data to client             22          0   33.77us     .0 Network

SQL ordered by Gets               DB/Inst: ORACLE/stbyoracle  Snaps: 2727-2728
-> Resources reported for PL/SQL code includes the resources used by all SQL
   statements called by the code.
-> %Total - Buffer Gets   as a percentage of Total Buffer Gets
-> %CPU   - CPU Time      as a percentage of Elapsed Time
-> %IO    - User I/O Time as a percentage of Elapsed Time
-> Total Buffer Gets:       3,399,948
-> Captured SQL account for   98.1% of Total

     Buffer                 Gets              Elapsed
      Gets   Executions   per Exec   %Total   Time (s)  %CPU   %IO    SQL Id
----------- ----------- ------------ ------ ---------- ----- ----- -------------
  3,241,728         120     27,014.4   95.3       14.4  99.5     0 82mps751cqh84
Module: SQL*Plus
select count(*) from Table1 where line=1 and owner in (select Table2.owner from
Table2 where Table2.owner=Table1.owner) order by owner

IOStat by Function summary        DB/Inst: ORACLE/stbyoracle  Snaps: 2727-2728
-> 'Data' columns suffixed with M,G,T,P are in multiples of 1024
    other columns suffixed with K,M,G,T,P are in multiples of 1000
-> ordered by (Data Read + Write) desc

                 Reads:  Reqs    Data   Writes:  Reqs    Data    Waits:    Avg
Function Name      Data per sec per sec    Data per sec per sec   Count    Time
--------------- ------- ------- ------- ------- ------- ------- ------- --------
LGWR                 3M     1.5   .022M     10M     3.6   .075M     678 368.73us
Others               7M    20.0   .052M      2M     1.0   .015M     629 100.16us
Buffer Cache Re      3M    21.0   .022M      0M     0.0      0M     251  11.95us
DBWR                 0M     0.0      0M      0M     0.1      0M      18    .00ns
Direct Reads         0M  1288.7      0M      0M     0.0      0M       0
Direct Writes        0M     0.0      0M      0M     0.0      0M       1    .00ns
RMAN                 0M     0.5      0M      0M     0.0      0M       0
TOTAL:              13M  1331.7   .097M     12M     4.8    .09M    1577 200.38us
                          ------------------------------------------------------

TEST CASE 2: this started to occur after a database restart:  
Now the I/O is recorded in IOStats and wait events, direct path read:

Top 10 Foreground Events by Total Wait Time
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                           Total Wait       Avg   % DB Wait
Event                                Waits Time (sec)      Wait   time Class
------------------------------ ----------- ---------- --------- ------ --------
DB CPU                                           23.7             98.4
direct path read                    22,134        4.8  217.85us   20.0 User I/O
PGA memory operation                 2,088         .1   28.85us     .2 Other
Disk file operations I/O             1,587          0   18.20us     .1 User I/O
SQL*Net message to client            1,861          0  817.30ns     .0 Network
db file sequential read                 97          0   13.43us     .0 User I/O
log file sync                            2          0  521.50us     .0 Commit
control file sequential read           174          0    5.08us     .0 System I
enq: RO - fast object reuse              1          0  849.00us     .0 Applicat
reliable message                         1          0  194.00us     .0 Other

SQL ordered by Gets               DB/Inst: ORACLE/stbyoracle  Snaps: 2711-2712
-> Resources reported for PL/SQL code includes the resources used by all SQL
   statements called by the code.
-> %Total - Buffer Gets   as a percentage of Total Buffer Gets
-> %CPU   - CPU Time      as a percentage of Elapsed Time
-> %IO    - User I/O Time as a percentage of Elapsed Time
-> Total Buffer Gets:       3,351,947
-> Captured SQL account for  101.1% of Total

     Buffer                 Gets              Elapsed
      Gets   Executions   per Exec   %Total   Time (s)  %CPU   %IO    SQL Id
----------- ----------- ------------ ------ ---------- ----- ----- -------------
  3,214,121         119     27,009.4   95.9       16.9  99.7  28.6 82mps751cqh84
Module: sqlplus@va1idevlclu0002 (TNS V1-V3)
select count(*) from Table1 where line=1 and owner in (select Table2.owner from
Table2 where Table2.owner=Table1.owner) order by owner


IOStat by Function summary        DB/Inst: ORACLE/stbyoracle  Snaps: 2711-2712
-> 'Data' columns suffixed with M,G,T,P are in multiples of 1024
    other columns suffixed with K,M,G,T,P are in multiples of 1000
-> ordered by (Data Read + Write) desc

                 Reads:  Reqs    Data   Writes:  Reqs    Data    Waits:    Avg
Function Name      Data per sec per sec    Data per sec per sec   Count    Time
--------------- ------- ------- ------- ------- ------- ------- ------- --------
Direct Reads      20.5G  1269.6 124.097      0M     0.0      0M   22.1K    .00ns
LGWR                 4M     1.8   .024M     10M     1.7   .059M     578 252.60us
Others               9M     6.4   .053M      2M     0.9   .012M     726  97.80us
Buffer Cache Re      0M     5.2      0M      0M     0.0      0M      77  12.99us
DBWR                 0M     0.0      0M      0M     0.1      0M      15    .00ns
RMAN                 0M     0.1      0M      0M     0.0      0M       0
TOTAL:            20.5G  1283.1 124.174     12M     2.6   .071M   23.5K   9.26us
                          ------------------------------------------------------


What could possibly be the cause of this unusual situation? The query response time is the same. The execution plan is the same. The amount of data in the table is the same. Why is Oracle reporting that it read 13 MB of data in test case 1, but 20.5 GB of data in test case 2?

I would also like to know what factors Oracle uses to determine that a buffer read should added to "Direct Reads". I recalled that Oracle used to record full table scan reads in the "db file scattered read" wait event. However, in the first test case, Oracle didn't add it to any I/O wait event, for some reason.

Thanks for your help in helping solve this unusual case.

John

and Connor said...

I would expect it is going to be related to the content of this blog post (which is an exadata one, but many principles are the same)

https://blogs.oracle.com/smartscan-deep-dive/when-bloggers-get-it-wrong-part-1

In a nutshell - there is a LOT of factors that influence a decision on direct read *including* how much of the table is deemed to current be in the buffer cache already.

So occasionally seeing a direct read "disappear" is not entirely unexpected.

Rating

  (2 ratings)

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

Comments

John, May 10, 2021 - 7:44 pm UTC

Hello Connor,

Thank you for helping me out on this one.

In test case 1, oracle reports that it read ONLY 13 MB of data, but as you can see from AWR report that "3,241,728" of gets were performed:

     Buffer                 Gets              Elapsed
      Gets   Executions   per Exec   %Total   Time (s)  %CPU   %IO    SQL Id
----------- ----------- ------------ ------ ---------- ----- ----- -------------
  3,241,728         120     27,014.4   95.3       14.4  99.5     0 82mps751cqh84
Module: SQL*Plus
select count(*) from Table1 where line=1 and owner in (select Table2.owner from
Table2 where Table2.owner=Table1.owner) order by owner


3,241,728 multiplied by 8k block size = 24 gigabytes! Why isn't Oracle reporting that 64gB of I/O? IOStat only shows that 13 MB of of Reads occurred. That is very peculiar. Is this an Oracle bug? It must be since it reports 64gB of buffers read by the query, but then states that only 13 MB of reads occurred.
Connor McDonald
May 12, 2021 - 7:07 am UTC

Nested loop style queries can easily visit and revisit rows and hence blocks in the buffer cache, yielding high buffer gets but minimal IO, eg

SQL> create table t1 as select rownum x from dual
  2  connect by level <= 500;

Table created.

SQL>
SQL> create table t2 as select rownum x from dual
  2  connect by level <= 500;

Table created.

SQL>
SQL> create table t3 as select rownum x from dual
  2  connect by level <= 500;

Table created.

SQL>
SQL> set autotrace on stat
SQL>
SQL> select /*+ leading(t1 t2 t3) use_nl(t2) use_nl(t3) */ count(*)
  2  from t1, t2, t3
  3  where t1.x != t2.x
  4  and t2.x != t3.x;

  COUNT(*)
----------
 124500500

1 row selected.


Statistics
----------------------------------------------------------
         19  recursive calls
         16  db block gets
     500014  consistent gets
          4  physical reads
       3180  redo size
        553  bytes sent via SQL*Net to client
        480  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          1  rows processed


Sorry, I don't think I'm being clear

John, May 12, 2021 - 5:00 pm UTC

Hello Connor,

"Nested loop style queries can easily visit and revisit rows and hence blocks in the buffer cache, yielding high buffer gets but minimal IO, eg"

But why isn't Oracle adding the 3,241,728 buffer cache / consistent reads to the "Buffer Cache Re" of the "IOStat by Function summary" AWR section? Oracle doesn't add the buffer read I/O to any category in the "IOStat by Function summary" AWR section. It is as if Oracle is hiding that I/O. I use "IOStat by Function summary" to find out how much total I/O is occurring in the database which includes how much of that I/O from consistent block reads. When I see that "IOStat by Function summary" AWR section shows that less than 100M of I/O occurred, then I conclude that the total I/O was low. However, the total I/O wasn't less than 100M because one query completed 3,241,728 of buffer gets which equals a total of 20gB! 

     Buffer                 Gets              Elapsed
      Gets   Executions   per Exec   %Total   Time (s)  %CPU   %IO    SQL Id
----------- ----------- ------------ ------ ---------- ----- ----- -------------
  3,241,728         120     27,014.4   95.3       14.4  99.5     0 82mps751cqh84
Module: SQL*Plus
select count(*) from Table1 where line=1 and owner in (select Table2.owner from
Table2 where Table2.owner=Table1.owner) order by owner

IOStat by Function summary        DB/Inst: ORACLE/stbyoracle  Snaps: 2727-2728
-> 'Data' columns suffixed with M,G,T,P are in multiples of 1024
    other columns suffixed with K,M,G,T,P are in multiples of 1000
-> ordered by (Data Read + Write) desc

                 Reads:  Reqs    Data   Writes:  Reqs    Data    Waits:    Avg
Function Name      Data per sec per sec    Data per sec per sec   Count    Time
--------------- ------- ------- ------- ------- ------- ------- ------- --------
LGWR                 3M     1.5   .022M     10M     3.6   .075M     678 368.73us
Others               7M    20.0   .052M      2M     1.0   .015M     629 100.16us
Buffer Cache Re      3M    21.0   .022M      0M     0.0      0M     251  11.95us
DBWR                 0M     0.0      0M      0M     0.1      0M      18    .00ns
Direct Reads         0M  1288.7      0M      0M     0.0      0M       0
Direct Writes        0M     0.0      0M      0M     0.0      0M       1    .00ns
RMAN                 0M     0.5      0M      0M     0.0      0M       0
TOTAL:              13M  1331.7   .097M     12M     4.8    .09M    1577 200.38us
                          ------------------------------------------------------

more

Connor and Chris don't just spend all day on AskTOM. You can also catch regular content via Connor's blog and Chris's blog. Or if video is more your thing, check out Connor's latest video and Chris's latest video from their Youtube channels. And of course, keep up to date with AskTOM via the official twitter account.

More to Explore

Performance

Get all the information about database performance in the Database Performance guide.