Nigel Noble's Oracle Blog

10/01/2013

11.2.0.3 Strange statistic, large transactions, dirty buffers and “direct path read”

Filed under: 11gR2, Performance — Nigel Noble @ 6:27 pm

Summary

I recently investigated an IO performance “spike” on a large 11.2.0.3 transactional system and I thought I would cover some interesting issues found. I am going to take the approach of detailing the observations made from our production and test systems and avoid attempting to cover how other versions of Oracle behave. The investigation also uncovers a confusing database statistic which we are currently discussing with Oracle Development so they can decide if this is an Oracle coding bug or a documentation issue.

The initial IO issue

We run a simple home grown database monitor which watches database wait events and sends an email alert if it detects either a single session waiting on a non-idle wait for a long time or the total number of database sessions concurrently waiting goes above a defined threshold. The monitor can give a number of false alerts but can also draw our attention to some more interesting events.

One day the monitor alerted me to two separate databases waiting on “log file sync” waits at exactly the same few seconds and affecting many hundreds of sessions. Both databases share the same storage array so the obvious place to start was to look at the storage statistics. We found a strange period lasting around 10 seconds long when both databases had a large increase in redo write service times and a few seconds when no IO was written at all. The first database we looked at seemed to show increase in disk service times for a very similar work load.  The second system showed a large increase in data file writes (500MB/sec) but without any matching increase in redo log writes. It seems the first database was slowed down by the second database flushing 5GB of data.

Where did 5GB of data file writes come from, and what triggered it?

Looking at the database we knew there were no corresponding redo writes, there were no obvious large sql statements reading or writing. We confirmed these writes were real and not something outside the database.

Database Checkpointing?

Did the instance flush a lot of dirty blocks down to disk? Our first idea was that Oracle version 11g  can decide to do “direct path read” for a serial object scan and this can cause dirty buffers (of the object) to be flushed to disk. So we checked the AWR wait data and could not find many “direct path read” wait events at all. We looked at all the checkpointing statistics and found the following surprise…

A large increase in “DBWR tablespace checkpoint buffers written” of about 750,000 buffers. Looking back over time we had not seen this occur before on the database so there must have been a triggering event. Oracle documentation shows the following for checkpointing:

http://docs.oracle.com/cd/E11882_01/server.112/e10713/startup.htm#BABGDACG

  • Tablespace and data file checkpoints: The database writes to disk all buffers modified by redo before a specific target. A tablespace checkpoint is a set of data file checkpoints, one for each data file in the tablespace. These checkpoints occur in a variety of situations, including making a tablespace read-only or taking it offline normal, shrinking a data file, or executing ALTER TABLESPACE BEGIN BACKUP.

Notes found using google searches  also suggest that statistic can be triggers by following:

  • - Caused by :
      Alter tablespace xxx offline
      Alter tablespace xxx begin backup
      Alter tablespace xxx read only
  • also caused by resizing a file smaller as well.

All the above examples would leave a message in the alert.log file and there is no indication that any of those had occured on our system.

What triggers ““DBWR tablespace checkpoint buffers written”?

AWR file statistics gave us the Tablespace name which had seen the increase in writes. Looking back at v$active_session_history we managed to find a possible triggering event. At the start of the issue, we found one session had also waited on “enq: KO – fast object checkpoint”. This session did not appear to do any “direct path reads” and only lasted a few seconds. Further investigated revealed why it did not do much IO…..

select col1,col2,col3 from very_large_table where rownum < 2

One of our developers wanted to collect a small random sample of data from a large 60GB table. All the queries restricted the number of rows which would be scanned using rownum. But it appears that in this case, Oracle has decided to use the 11g serial direct path method and requests any dirty blocks be flushed first to disk…. to then actually read one block using “direct path read” and then stop. This now explains the triggering event and also why we could not see a large amount of “direct path read” requests.

A number of questions then arise.

Why did I flush 5GB of changes down to disk when I have a fast_start_mttr_target set to 10 minutes?  ( There were no sign of any recent large DML on the table)

Did I really cause all dirty blocks from the tablespace to be flushed as implied by the “DBWR tablespace checkpoint buffers written”?

In a small test system I re-produced the issue of a direct path scan causing “direct path read”. When I updated the table to cause dirty blocks the direct IO first waited on the “enq: KO – fast object checkpoint” and also updated the tablespace checkpoint statistic. I then created a copy of my test table (in the same Tablespace) and updated both tables (in separate transactions) to cause both objects to have dirty blocks.  Using a query on v$bh (a view of the buffer cache)  I was able to see that when I trigger the “enq: KO – fast object checkpoint” on one object, the other object kept it’s dirty blocks in the cache. 

So i had  proven that Oracle does only flush the dirty objects of one object and not the complete tablespace. So it really looks like Oracle is using the wrong statistic. When we trigger the direct IO using a parallel query, Oracle updates the statistic “DBWR parallel query checkpoint buffers written” which makes sense.

Looking at the available statistics (in 11.2) it really looks like Oracle does not have an appropriate statistic to describe what it is doing ( or at the very least does not clearly describe this event in the documentation).


SQL> select name from v$statname where name like '%DBW%check%';

NAME
----------------------------------------------------------------
DBWR checkpoint buffers written
DBWR thread checkpoint buffers written
DBWR tablespace checkpoint buffers written
DBWR parallel query checkpoint buffers written
DBWR checkpoints

Why did I have 5GB of dirty buffers on one object in my buffer cache?

 
If we ignore the misleading statistic, I still needed to understand why Oracle flushed so many buffers to disk. I looked at v$bh on our production database and still found this object with over 500,000 dirty buffers regardless of the time of day I looked.  My “fast_start_mttr_target” was set to 10 minutes and there had not been any large DML for many hours.
 
I created a small test case for the issue and managed to stumble on what the problem was…..
 
Note: I have included the output from a number of the tests at the very end of this blog item.
 
Using a small test database (Which happened to be one built using Kevin Closson’s SLOB benchmark) I ran the following test.
 
  •  I updated 10000 rows of a table
  • do NOT commit the transaction
  • verify the v$bh DOES have many dirty blocks
  • Issue “alter system switch logfile” and rotate around all my online redo logs [in a separate session]
  • verify in v$bh that all the dirty blocks of the object are flushed.
  • now issue the COMMIT of the transaction

When we now look back in v$bh we find that a number of buffers on that object are dirty again. This is due to the commit-cleanout [link to Jonathan Lewis blog http://jonathanlewis.wordpress.com/2009/06/16/clean-it-up/] occurring on 10% worth of buffers. Because my transaction lasts so long, Oracle attempts to perform ” block cleanout” on a proportion of buffers found in the buffer cache. I then continue my test as follows.

  • I now continue to issue many “alter system switch logfile” commands and it does not matter how long I wait Oracle does not flush these dirty blocks from the buffer cache.
  • I then issue a Full Table Scan of the table and regardless of the existence of ” rownum<2″ or not, because the size of the object means Oracle decides to do a “direct path read”,  Oracle first  issues a “enq: KO fast object checkpoint” and flushes the dirty blocks down.

Block Cleanout:

My production table is 60GB in size and holds 8 day’s worth of data. Every day over night we delete 1 day of data in a single transaction as part of a archiving housekeeping job.

So the issue of why I have so many dirty blocks appears to be due to Block Cleanout. I have a 100GB buffer cache so that means a commit could in theory touch 1310720 blocks at commit with commit-cleanout. It seems then these blocks only get flushed as and when the blocks are used by other sessions (natural usage). So it’s possible for many of these dirty blocks to sit in the cache until some unsuspecting user attempts to do a direct-path read on the table [at which point all the dirty blocks are immediately flushed down]

The way forward

We are considering changes our daily archive job to “chunk” the delete into smaller transactions and then possibly look to issue a small “direct path read” on the table [using rownum < 2] to flush out the dirty buffers after every chunk is deleted. We hope by making these changes we can reduce the build-up of dirty blocks and minimize the effect of something triggering a sudden large flush of buffers on our transactional system. I have been talking to Oracle Development about both the statistic name used, how the database decides to implement “direct path read” and also try and understand more about why commit-cleanout blocks are left in the cache so long. I’ll update this blog item if I get  more information.

—- Output of various test runs I made —-

Simple test to show the which DBWR checkpoint statistics get updated:

SQL>
SQL> @create_fresh_large_cf1.sql
SQL>
SQL> rem   Create a larger copy of the SLOB CF1 table and also create it in the default buffer pool
SQL> rem   Maintain the pctfree settings so that we also keep one row per block
SQL>
SQL> drop table user1.cf1_large purge;

Table dropped.

SQL>
SQL> rem create table 5 times larger then the original
SQL>
SQL> create table user1.cf1_large tablespace iops pctfree 99 storage (buffer_pool default) as
  2  select * from user1.cf1 union all
  3  select * from user1.cf1 union all
  4  select * from user1.cf1 union all
  5  select * from user1.cf1 union all
  6  select * from user1.cf1 ;

Table created.

SQL>
SQL> rem collect stats on the table
SQL>
SQL> exec DBMS_STATS.GATHER_TABLE_STATS('USER1', 'cf1_large', estimate_percent=>100, block_sample=>TRUE, degree=>2);

PL/SQL procedure successfully completed.

SQL>
SQL> @cf1_payload_test2
SQL> rem restart the instance
SQL> rem
SQL>
SQL> startup force pfile=create11_TS_TEST.ora
ORACLE instance started.

Total System Global Area 1353027584 bytes
Fixed Size                  2228104 bytes
Variable Size            1107296376 bytes
Database Buffers          218103808 bytes
Redo Buffers               25399296 bytes
Database mounted.
Database opened.
SQL>
SQL> connect / as sysdba
Connected.
SQL>
SQL> rem BASELINE of...
SQL> rem     Show count of blocks in v$bh for objects with more than 1000 blocks in buffer cache
SQL> rem     db checkpoint/block cleanout stats and buffer cache before we start.
SQL> rem     also dump waits if they exit for "enq: KO fast object checkpoint"
SQL>
SQL> @check_status2
SQL>
SQL> set echo off

no rows selected

NAME                                                    VALUE
-------------------------------------------------- ----------
DBWR checkpoint buffers written                             0
DBWR checkpoints                                            1
DBWR parallel query checkpoint buffers written              0
DBWR tablespace checkpoint buffers written                  0
DBWR thread checkpoint buffers written                      0

no rows selected

SQL>
SQL> rem update first 10000 blocks with a non commited transaction
SQL>
SQL> update user1.cf1_large set c20 = c20
  2         where rownum < 10001; 10000 rows updated. SQL>
SQL> rem check status, transaction NOT yet commited
SQL>
SQL> @check_status2
SQL>
SQL> set echo off

      OBJD STATUS                         Dirty Blocks?     COUNT(*)
---------- ------------------------------ --------------- ----------
     15392 xcur                           Y                    10000

NAME                                                    VALUE
-------------------------------------------------- ----------
DBWR checkpoint buffers written                             0
DBWR checkpoints                                            1
DBWR parallel query checkpoint buffers written              0
DBWR tablespace checkpoint buffers written                  0
DBWR thread checkpoint buffers written                      0

no rows selected

SQL>
SQL> rem - now COMMIT the transaction
SQL>
SQL> COMMIT;

Commit complete.

SQL>
SQL> @check_status2
SQL>
SQL> set echo off

      OBJD STATUS                         Dirty Blocks?     COUNT(*)
---------- ------------------------------ --------------- ----------
     15392 xcur                           Y                    10000

NAME                                                    VALUE
-------------------------------------------------- ----------
DBWR checkpoint buffers written                             0
DBWR checkpoints                                            1
DBWR parallel query checkpoint buffers written              0
DBWR tablespace checkpoint buffers written                  0
DBWR thread checkpoint buffers written                      0

no rows selected

SQL>
SQL> rem - now trigger a direct path read of the object. Object is large enough to want to do direct path IO
SQL> rem - based on size of the buffer cache and object in this example .. even though we only want first row of the table
SQL>
SQL> select /*+FULL(x)*/ count(c20) from user1.cf1_large x where rownum < 2;
COUNT(C20)
----------
1
SQL>
SQL>
SQL> rem now check status of dirty blocks and confirm they have now been flushed and also the Tablespace checkpoint reported.
SQL> @check_status2
SQL>
SQL> set echo off

      OBJD STATUS                         Dirty Blocks?     COUNT(*)
---------- ------------------------------ --------------- ----------
     15392 xcur                           N                    10008

NAME                                                    VALUE
-------------------------------------------------- ----------
DBWR checkpoint buffers written                         10000
DBWR checkpoints                                            2
DBWR parallel query checkpoint buffers written              0
DBWR tablespace checkpoint buffers written              10000  <--- DWR tablespace incremented
DBWR thread checkpoint buffers written                      0

EVENT                                    TOTAL_WAITS TIME_WAITED_MICRO
---------------------------------------- ----------- -----------------
enq: KO - fast object checkpoint                   1            366763

SQL>
SQL>
SQL>
SQL>
SQL>
SQL>
SQL>
SQL> rem
SQL> rem NOTE: Now run the test a second time but this time we will trigger using PARALLEL query
SQL> rem
SQL>
SQL> @cf1_payload_test2_parallel
SQL> rem restart the instance
SQL> rem
SQL>
SQL> startup force pfile=create11_TS_TEST.ora
ORACLE instance started.

Total System Global Area 1353027584 bytes
Fixed Size                  2228104 bytes
Variable Size            1107296376 bytes
Database Buffers          218103808 bytes
Redo Buffers               25399296 bytes
Database mounted.
Database opened.
SQL>
SQL> connect / as sysdba
Connected.
SQL>
SQL> rem BASELINE of...
SQL> rem     Show count of blocks in v$bh for objects with more than 1000 blocks in buffer cache
SQL> rem     db checkpoint/block cleanout stats and buffer cache before we start.
SQL> rem     also dump waits if they exit for "enq: KO fast object checkpoint"
SQL>
SQL> @check_status2
SQL>
SQL> set echo off

no rows selected

NAME                                                    VALUE
-------------------------------------------------- ----------
DBWR checkpoint buffers written                            11
DBWR checkpoints                                           19
DBWR parallel query checkpoint buffers written              0
DBWR tablespace checkpoint buffers written                  0
DBWR thread checkpoint buffers written                      0

no rows selected

SQL>
SQL> rem update first 10000 blocks with a non commited transaction
SQL>
SQL> update user1.cf1_large set c20 = c20
  2         where rownum < 10001; 10000 rows updated. SQL>
SQL> rem check status, transaction NOT yet commited
SQL>
SQL> @check_status2
SQL>
SQL> set echo off

      OBJD STATUS                         Dirty Blocks?     COUNT(*)
---------- ------------------------------ --------------- ----------
     15392 xcur                           Y                    10000

NAME                                                    VALUE
-------------------------------------------------- ----------
DBWR checkpoint buffers written                            11
DBWR checkpoints                                           19
DBWR parallel query checkpoint buffers written              0
DBWR tablespace checkpoint buffers written                  0
DBWR thread checkpoint buffers written                      0

no rows selected

SQL>
SQL> rem - now COMMIT the transaction
SQL>
SQL> COMMIT;

Commit complete.

SQL>
SQL> @check_status2
SQL>
SQL> set echo off

      OBJD STATUS                         Dirty Blocks?     COUNT(*)
---------- ------------------------------ --------------- ----------
     15392 xcur                           Y                    10000

NAME                                                    VALUE
-------------------------------------------------- ----------
DBWR checkpoint buffers written                            11
DBWR checkpoints                                           19
DBWR parallel query checkpoint buffers written              0
DBWR tablespace checkpoint buffers written                  0
DBWR thread checkpoint buffers written                      0

no rows selected

SQL>
SQL> rem - now trigger a direct path read of the object. This time using parallel query
SQL>
SQL> select /*+FULL(x) PARALLEL(x,2)*/ count(c20) from user1.cf1_large x where rownum < 2; COUNT(C20) ----------          1 SQL>
SQL>
SQL> rem now check status of dirty blocks and confirm they have now been flushed and also the Tablespace checkpoint reported.
SQL> @check_status2
SQL>
SQL> set echo off

      OBJD STATUS                         Dirty Blocks?     COUNT(*)
---------- ------------------------------ --------------- ----------
     15392 xcur                           N                    10008

NAME                                                    VALUE
-------------------------------------------------- ----------
DBWR checkpoint buffers written                         10011
DBWR checkpoints                                           20
DBWR parallel query checkpoint buffers written          10000 < Parallel query uses parallel checkpoint stat
DBWR tablespace checkpoint buffers written                  0
DBWR thread checkpoint buffers written                      0

EVENT                                    TOTAL_WAITS TIME_WAITED_MICRO
---------------------------------------- ----------- -----------------
enq: KO - fast object checkpoint                   1            349529

SQL>
SQL>
SQL>
SQL>
SQL>
SQL>
SQL>
SQL> exit

Test to show only one object actually gets flushed when direct path is issued and the DBWR tablespace statistic is updated

SQL>
SQL> @cf1_payload_test4
SQL> rem restart the instance
SQL> rem
SQL>
SQL> startup force pfile=create11_TS_TEST4.ora
ORACLE instance started.

Total System Global Area 1670369280 bytes
Fixed Size                  2228864 bytes
Variable Size            1107299712 bytes
Database Buffers          536870912 bytes
Redo Buffers               23969792 bytes
Database mounted.
Database opened.
SQL>
SQL> connect / as sysdba
Connected.
SQL>
SQL> rem BASELINE of...
SQL> rem     Show count of blocks in v$bh for objects with more than 1000 blocks in buffer cache
SQL> rem     db checkpoint/block cleanout stats and buffer cache before we start.
SQL> rem     also dump waits if they exit for "enq: KO fast object checkpoint"
SQL>
SQL> @check_status2
SQL>
SQL> set echo off

no rows selected

no rows selected

NAME                                                    VALUE
-------------------------------------------------- ----------
DBWR checkpoint buffers written                             1
DBWR checkpoints                                            5
DBWR parallel query checkpoint buffers written              0
DBWR tablespace checkpoint buffers written                  0
DBWR thread checkpoint buffers written                      0

SQL>
SQL> rem update all rows in two seperate tables (two different schema)
SQL>
SQL> update user1.cf1 set c20 = c20;

10000 rows updated.

SQL> commit;

Commit complete.

SQL>
SQL> update user2.cf1 set c20 = c20;

10000 rows updated.

SQL> commit;

Commit complete.

SQL>
SQL>
SQL> rem check status of dirty blocks by object id
SQL>
SQL> @check_status2
SQL>
SQL> set echo off

      OBJD STATUS                         Dirty Blocks?     COUNT(*)
---------- ------------------------------ --------------- ----------
     14356 xcur                           Y                    10000
     14353 xcur                           Y                    10000

no rows selected

NAME                                                    VALUE
-------------------------------------------------- ----------
DBWR checkpoint buffers written                             1
DBWR checkpoints                                            5
DBWR parallel query checkpoint buffers written              0
DBWR tablespace checkpoint buffers written                  0
DBWR thread checkpoint buffers written                      0

SQL>
SQL> rem - now trigger a direct path read of one of the objects  only
SQL>
SQL> select /*+FULL(x)*/ count(c20) from user1.cf1 x where rownum < 2; COUNT(C20) ----------          1 SQL>
SQL>
SQL> rem now check status of dirty blocks and confirm they have now been flushed and also the Tablespace checkpoint reported.
SQL> @check_status2
SQL>
SQL> set echo off

      OBJD STATUS                         Dirty Blocks?     COUNT(*)
---------- ------------------------------ --------------- ----------
     14356 xcur                           Y                    10000
     14353 xcur                           N                    10001  <-- only flushed one objects buffers

EVENT                                    TOTAL_WAITS TIME_WAITED_MICRO
---------------------------------------- ----------- -----------------
enq: KO - fast object checkpoint                   1            286112

NAME                                                    VALUE
-------------------------------------------------- ----------
DBWR checkpoint buffers written                         10001
DBWR checkpoints                                            6
DBWR parallel query checkpoint buffers written              0
DBWR tablespace checkpoint buffers written              10000 <-- still updated tablespace stat
DBWR thread checkpoint buffers written                      0

SQL>
SQL>
SQL>
SQL>
SQL>
SQL>
SQL>
SQL> rem
SQL> rem NOTE: Now run the test a second time But this time we will put Tablespace in READ ONLY state.
SQL> rem
SQL>
SQL> @cf1_payload_test4_readonly.sql
SQL> rem restart the instance
SQL> rem
SQL>
SQL> startup force pfile=create11_TS_TEST4.ora
ORACLE instance started.

Total System Global Area 1670369280 bytes
Fixed Size                  2228864 bytes
Variable Size            1107299712 bytes
Database Buffers          536870912 bytes
Redo Buffers               23969792 bytes
Database mounted.
Database opened.
SQL>
SQL> connect / as sysdba
Connected.
SQL>
SQL> rem BASELINE of...
SQL> rem     Show count of blocks in v$bh for objects with more than 1000 blocks in buffer cache
SQL> rem     db checkpoint/block cleanout stats and buffer cache before we start.
SQL> rem     also dump waits if they exit for "enq: KO fast object checkpoint"
SQL>
SQL> @check_status2
SQL>
SQL> set echo off

      OBJD STATUS                         Dirty Blocks?     COUNT(*)
---------- ------------------------------ --------------- ----------
     14356 xcur                           N                    10000

no rows selected

NAME                                                    VALUE
-------------------------------------------------- ----------
DBWR checkpoint buffers written                           266
DBWR checkpoints                                           27
DBWR parallel query checkpoint buffers written              0
DBWR tablespace checkpoint buffers written                  0
DBWR thread checkpoint buffers written                      0

SQL>
SQL> rem update all rows in two seperate tables (two different schema)
SQL>
SQL> update user1.cf1 set c20 = c20;

10000 rows updated.

SQL> commit;

Commit complete.

SQL>
SQL> update user2.cf1 set c20 = c20;

10000 rows updated.

SQL> commit;

Commit complete.

SQL>
SQL>
SQL> rem check status of dirty blocks by object id
SQL>
SQL> @check_status2
SQL>
SQL> set echo off

      OBJD STATUS                         Dirty Blocks?     COUNT(*)
---------- ------------------------------ --------------- ----------
     14356 cr                             N                    10000
     14356 xcur                           Y                    10000
     14353 xcur                           Y                    10000

no rows selected

NAME                                                    VALUE
-------------------------------------------------- ----------
DBWR checkpoint buffers written                           266
DBWR checkpoints                                           27
DBWR parallel query checkpoint buffers written              0
DBWR tablespace checkpoint buffers written                  0
DBWR thread checkpoint buffers written                      0

SQL>
SQL> rem - now make tablespace read only to force all objects in tablespace to flush
SQL>
SQL> alter tablespace iops read only;

Tablespace altered.

SQL> alter tablespace iops read write;

Tablespace altered.

SQL>
SQL> rem now check status of dirty blocks and confirm they have now been flushed and also the Tablespace checkpoint reported.
SQL> @check_status2
SQL>
SQL> set echo off

      OBJD STATUS                         Dirty Blocks?     COUNT(*)
---------- ------------------------------ --------------- ----------
     14353 free                           N                    10001  <-- Both objects buffer flushed
     14356 free                           N                    20000

no rows selected

NAME                                                    VALUE
-------------------------------------------------- ----------
DBWR checkpoint buffers written                         20266
DBWR checkpoints                                           28
DBWR parallel query checkpoint buffers written              0
DBWR tablespace checkpoint buffers written              20000 <-- Tablespace stat correctly used in this case
DBWR thread checkpoint buffers written                      0

Test to show the effect of commit-cleanout buffer left and not able to be flushed until we do direct IO

Test also used to show difference of block cleanout between the first time the object is created and the second time when blocks from the previous transaction are cleaned.

SQL>
SQL> @create_fresh_large_cf1.sql
SQL>
SQL> rem   Create a larger copy of the SLOB CF1 table and also create it in the default buffer pool
SQL> rem   Maintain the pctfree settings so that we also keep one row per block
SQL>
SQL> drop table user1.cf1_large purge;

Table dropped.

SQL>
SQL> rem create table 5 times larger then the original
SQL>
SQL> create table user1.cf1_large tablespace iops pctfree 99 storage (buffer_pool default) as
  2  select * from user1.cf1 union all
  3  select * from user1.cf1 union all
  4  select * from user1.cf1 union all
  5  select * from user1.cf1 union all
  6  select * from user1.cf1 ;

Table created.

SQL>
SQL> rem collect stats on the table
SQL>
SQL> exec DBMS_STATS.GATHER_TABLE_STATS('USER1', 'cf1_large', estimate_percent=>100, block_sample=>TRUE, degree=>2);

PL/SQL procedure successfully completed.

SQL>
SQL> @cf1_payload
SQL> rem restart the instance
SQL> rem
SQL>
SQL> startup force pfile=create11_TS_TEST.ora
ORACLE instance started.

Total System Global Area 1353027584 bytes
Fixed Size                  2228104 bytes
Variable Size            1107296376 bytes
Database Buffers          218103808 bytes
Redo Buffers               25399296 bytes
Database mounted.
Database opened.
SQL>
SQL> rem reconnect
SQL>
SQL> connect / as sysdba
Connected.
SQL>
SQL> rem BASELINE of...
SQL> rem     Show count of blocks in v$bh for objects with more than 1000 blocks in buffer cache
SQL> rem     db checkpoint/block cleanout stats and buffer cache before we start.
SQL> rem     also dump waits if they exit for "enq: KO fast object checkpoint"
SQL>
SQL> @check_status
SQL>
SQL> set echo off

no rows selected

no rows selected

NAME                                                    VALUE
-------------------------------------------------- ----------
DBWR checkpoint buffers written                             0
DBWR checkpoints                                            2
DBWR parallel query checkpoint buffers written              0
DBWR tablespace checkpoint buffers written                  0
DBWR thread checkpoint buffers written                      0
active txn count during cleanout                            0
cleanout - number of ktugct calls                          62
cleanouts and rollbacks - consistent read gets              0
cleanouts only - consistent read gets                      62
commit cleanouts                                           39
commit cleanouts successfully completed                    39
commit txn count during cleanout                           62
deferred (CURRENT) block cleanout applications             37
deferred CUR cleanouts (index blocks)                       0
immediate (CR) block cleanout applications                 62
immediate (CURRENT) block cleanout applications             1
immediate CR cleanouts (index blocks)                       0

17 rows selected.

SQL>
SQL> rem update first 10000 blocks with a non commited transaction
SQL>
SQL> update user1.cf1_large set c20 = c20
  2         where rownum < 10001; 10000 rows updated. SQL>
SQL> rem check status, transaction NOT yet commited
SQL>
SQL> @check_status
SQL>
SQL> set echo off

      OBJD STATUS                         Dirty Blocks?     COUNT(*)
---------- ------------------------------ --------------- ----------
     15377 xcur                           Y                    10000
     15377 cr                             N                     3935

no rows selected

NAME                                                    VALUE
-------------------------------------------------- ----------
DBWR checkpoint buffers written                             0
DBWR checkpoints                                            2
DBWR parallel query checkpoint buffers written              0
DBWR tablespace checkpoint buffers written                  0
DBWR thread checkpoint buffers written                      0
active txn count during cleanout                           17
cleanout - number of ktugct calls                          86
cleanouts and rollbacks - consistent read gets              0
cleanouts only - consistent read gets                      69
commit cleanouts                                          120
commit cleanouts successfully completed                   120
commit txn count during cleanout                           71
deferred (CURRENT) block cleanout applications             91
deferred CUR cleanouts (index blocks)                       0
immediate (CR) block cleanout applications                 69
immediate (CURRENT) block cleanout applications             7
immediate CR cleanouts (index blocks)                       0

17 rows selected.

SQL>
SQL> rem in another session issue 10 switch logs and then check status of dirty blocks on the cache
SQL> rem we only have 3 online logs in this database.
SQL> host sqlplus "/ as sysdba" @switchlogs.sql

SQL>
SQL> @check_status
SQL>
SQL> set echo off

      OBJD STATUS                         Dirty Blocks?     COUNT(*)
---------- ------------------------------ --------------- ----------
     15377 cr                             N                     3934
     15377 xcur                           N                    10008

no rows selected

NAME                                                    VALUE
-------------------------------------------------- ----------
DBWR checkpoint buffers written                         10551  <-- dirty buffers written
DBWR checkpoints                                           12
DBWR parallel query checkpoint buffers written              0
DBWR tablespace checkpoint buffers written                  0
DBWR thread checkpoint buffers written                  10551
active txn count during cleanout                           17
cleanout - number of ktugct calls                          86
cleanouts and rollbacks - consistent read gets              0
cleanouts only - consistent read gets                      69
commit cleanouts                                          120
commit cleanouts successfully completed                   120
commit txn count during cleanout                           71
deferred (CURRENT) block cleanout applications             91
deferred CUR cleanouts (index blocks)                       0
immediate (CR) block cleanout applications                 69
immediate (CURRENT) block cleanout applications             7
immediate CR cleanouts (index blocks)                       0

17 rows selected.

SQL>
SQL> rem - now COMMIT the transaction and see commit-cleanout blocks come back
SQL> rem - consistent with 10% of the buffer cache worth of blocks get touched.
SQL>
SQL> COMMIT;

Commit complete.

SQL>
SQL> @check_status
SQL>
SQL> set echo off

      OBJD STATUS                         Dirty Blocks?     COUNT(*)
---------- ------------------------------ --------------- ----------
     15377 cr                             N                     3934
     15377 xcur                           Y                     2600
     15377 xcur                           N                     7408

no rows selected

NAME                                                    VALUE
-------------------------------------------------- ----------
DBWR checkpoint buffers written                         10551
DBWR checkpoints                                           12
DBWR parallel query checkpoint buffers written              0
DBWR tablespace checkpoint buffers written                  0
DBWR thread checkpoint buffers written                  10551
active txn count during cleanout                           17
cleanout - number of ktugct calls                          86
cleanouts and rollbacks - consistent read gets              0
cleanouts only - consistent read gets                      69
commit cleanouts                                         2720
commit cleanouts successfully completed                  2720
commit txn count during cleanout                           71
deferred (CURRENT) block cleanout applications             91
deferred CUR cleanouts (index blocks)                       0
immediate (CR) block cleanout applications                 69
immediate (CURRENT) block cleanout applications             7
immediate CR cleanouts (index blocks)                       0

17 rows selected.

SQL>
SQL>
SQL> rem now force many multiple switch logs and see the dirty commit-cleanout blocks do not flush
SQL>
SQL> host sqlplus "/ as sysdba" @switchlogs.sql

SQL> host sqlplus "/ as sysdba" @switchlogs.sql

SQL>
SQL> @check_status
SQL>
SQL> set echo off

      OBJD STATUS                         Dirty Blocks?     COUNT(*)
---------- ------------------------------ --------------- ----------
     15377 cr                             N                     3934
     15377 xcur                           Y                     2600  <-- we still have these dirty buffers
     15377 xcur                           N                     7408

no rows selected

NAME                                                    VALUE
-------------------------------------------------- ----------
DBWR checkpoint buffers written                         10552
DBWR checkpoints                                           32
DBWR parallel query checkpoint buffers written              0
DBWR tablespace checkpoint buffers written                  0
DBWR thread checkpoint buffers written                  10552
active txn count during cleanout                           17
cleanout - number of ktugct calls                          86
cleanouts and rollbacks - consistent read gets              0
cleanouts only - consistent read gets                      69
commit cleanouts                                         2720 <--- seems we also did similar commit cleanouts
commit cleanouts successfully completed                  2720
commit txn count during cleanout                           71
deferred (CURRENT) block cleanout applications             91
deferred CUR cleanouts (index blocks)                       0
immediate (CR) block cleanout applications                 69
immediate (CURRENT) block cleanout applications             7
immediate CR cleanouts (index blocks)                       0

17 rows selected.

SQL>
SQL> rem - now trigger a direct path read of the object. Object is large enough to want to do direct path IO
SQL> rem - based on size of the buffer cache and object in this example .. even though we only want first row of the table
SQL>
SQL> select /*+FULL(x)*/ count(c20) from user1.cf1_large x where rownum < 2;
COUNT(C20)
----------
1
SQL>
SQL>
SQL> rem now check status of dirty blocks and confirm they have now been flushed and also the Tablespace checkpoint reported.
SQL> @check_status
SQL>
SQL> set echo off

      OBJD STATUS                         Dirty Blocks?     COUNT(*)
---------- ------------------------------ --------------- ----------
     15377 cr                             N                     3934
     15377 xcur                           N                    10008 <-- only now are the commit-cleanout flushed

EVENT                                    TOTAL_WAITS TIME_WAITED_MICRO
---------------------------------------- ----------- -----------------
enq: KO - fast object checkpoint                   1             65071

NAME                                                    VALUE
-------------------------------------------------- ----------
DBWR checkpoint buffers written                         13152
DBWR checkpoints                                           33
DBWR parallel query checkpoint buffers written              0
DBWR tablespace checkpoint buffers written               2600
DBWR thread checkpoint buffers written                  10552
active txn count during cleanout                           17
cleanout - number of ktugct calls                          86
cleanouts and rollbacks - consistent read gets              0
cleanouts only - consistent read gets                      69
commit cleanouts                                         2720
commit cleanouts successfully completed                  2720
commit txn count during cleanout                           71
deferred (CURRENT) block cleanout applications             91
deferred CUR cleanouts (index blocks)                       0
immediate (CR) block cleanout applications                 69
immediate (CURRENT) block cleanout applications             7
immediate CR cleanouts (index blocks)                       0

17 rows selected.

SQL>
SQL>
SQL>
SQL>
SQL>
SQL>
SQL>
SQL> rem
SQL> rem NOTE: Now run the test a second time without re-creating the test table to see effect of block cleanout on the second run
SQL> rem
SQL>
SQL> @cf1_payload
SQL> rem restart the instance
SQL> rem
SQL>
SQL> startup force pfile=create11_TS_TEST.ora
ORACLE instance started.

Total System Global Area 1353027584 bytes
Fixed Size                  2228104 bytes
Variable Size            1107296376 bytes
Database Buffers          218103808 bytes
Redo Buffers               25399296 bytes
Database mounted.
Database opened.
SQL>
SQL> rem reconnect
SQL>
SQL> connect / as sysdba
Connected.
SQL>
SQL> rem BASELINE of...
SQL> rem     Show count of blocks in v$bh for objects with more than 1000 blocks in buffer cache
SQL> rem     db checkpoint/block cleanout stats and buffer cache before we start.
SQL> rem     also dump waits if they exit for "enq: KO fast object checkpoint"
SQL>
SQL> @check_status
SQL>
SQL> set echo off

no rows selected

no rows selected

NAME                                                    VALUE
-------------------------------------------------- ----------
DBWR checkpoint buffers written                             0
DBWR checkpoints                                            0
DBWR parallel query checkpoint buffers written              0
DBWR tablespace checkpoint buffers written                  0
DBWR thread checkpoint buffers written                      0
active txn count during cleanout                            0
cleanout - number of ktugct calls                           0
cleanouts and rollbacks - consistent read gets              0
cleanouts only - consistent read gets                       0
commit cleanouts                                           39
commit cleanouts successfully completed                    39
commit txn count during cleanout                            0
deferred (CURRENT) block cleanout applications             35
deferred CUR cleanouts (index blocks)                       0
immediate (CR) block cleanout applications                  0
immediate (CURRENT) block cleanout applications             1
immediate CR cleanouts (index blocks)                       0

17 rows selected.

SQL>
SQL> rem update first 10000 blocks with a non commited transaction
SQL>
SQL> update user1.cf1_large set c20 = c20
  2         where rownum < 10001; 10000 rows updated. SQL>
SQL> rem check status, transaction NOT yet commited
SQL>
SQL> @check_status
SQL>
SQL> set echo off

      OBJD STATUS                         Dirty Blocks?     COUNT(*)
---------- ------------------------------ --------------- ----------
     15377 xcur                           Y                    10000

no rows selected

NAME                                                    VALUE
-------------------------------------------------- ----------
DBWR checkpoint buffers written                             0
DBWR checkpoints                                            0
DBWR parallel query checkpoint buffers written              0
DBWR tablespace checkpoint buffers written                  0
DBWR thread checkpoint buffers written                      0
active txn count during cleanout                            0
cleanout - number of ktugct calls                        7400  <-- this seems to be the cleanout on rest of the other blocks not included before
cleanouts and rollbacks - consistent read gets              0
cleanouts only - consistent read gets                    7400
commit cleanouts                                           54
commit cleanouts successfully completed                    54
commit txn count during cleanout                         7400
deferred (CURRENT) block cleanout applications           2642
deferred CUR cleanouts (index blocks)                       0
immediate (CR) block cleanout applications               7400
immediate (CURRENT) block cleanout applications             7
immediate CR cleanouts (index blocks)                       0

17 rows selected.

SQL>
SQL> rem in another session issue 10 switch logs and then check status of dirty blocks on the cache
SQL>
SQL> host sqlplus "/ as sysdba" @switchlogs.sql

SQL>
SQL> @check_status
SQL>
SQL> set echo off

      OBJD STATUS                         Dirty Blocks?     COUNT(*)
---------- ------------------------------ --------------- ----------
     15377 xcur                           N                    10008

no rows selected

NAME                                                    VALUE
-------------------------------------------------- ----------
DBWR checkpoint buffers written                         10421
DBWR checkpoints                                           10
DBWR parallel query checkpoint buffers written              0
DBWR tablespace checkpoint buffers written                  0
DBWR thread checkpoint buffers written                  10421
active txn count during cleanout                            0
cleanout - number of ktugct calls                        7400
cleanouts and rollbacks - consistent read gets              0
cleanouts only - consistent read gets                    7400
commit cleanouts                                           54
commit cleanouts successfully completed                    54
commit txn count during cleanout                         7400
deferred (CURRENT) block cleanout applications           2642
deferred CUR cleanouts (index blocks)                       0
immediate (CR) block cleanout applications               7400
immediate (CURRENT) block cleanout applications             7
immediate CR cleanouts (index blocks)                       0

17 rows selected.

SQL>
SQL> rem - now COMMIT the transaction and see commit-cleanout blocks come back
SQL>
SQL> COMMIT;

Commit complete.

SQL>
SQL> @check_status
SQL>
SQL> set echo off

      OBJD STATUS                         Dirty Blocks?     COUNT(*)
---------- ------------------------------ --------------- ----------
     15377 xcur                           Y                     2600
     15377 xcur                           N                     7408

no rows selected

NAME                                                    VALUE
-------------------------------------------------- ----------
DBWR checkpoint buffers written                         10421
DBWR checkpoints                                           10
DBWR parallel query checkpoint buffers written              0
DBWR tablespace checkpoint buffers written                  0
DBWR thread checkpoint buffers written                  10421
active txn count during cleanout                            0
cleanout - number of ktugct calls                        7400
cleanouts and rollbacks - consistent read gets              0
cleanouts only - consistent read gets                    7400
commit cleanouts                                         2654
commit cleanouts successfully completed                  2654
commit txn count during cleanout                         7400
deferred (CURRENT) block cleanout applications           2642
deferred CUR cleanouts (index blocks)                       0
immediate (CR) block cleanout applications               7400
immediate (CURRENT) block cleanout applications             7
immediate CR cleanouts (index blocks)                       0

17 rows selected.

SQL>
SQL>
SQL> rem now force many multiple switch logs and see the dirty commit-cleanout blocks do not flush
SQL>
SQL> host sqlplus "/ as sysdba" @switchlogs.sql

SQL> host sqlplus "/ as sysdba" @switchlogs.sql

SQL>
SQL> @check_status
SQL>
SQL> set echo off

      OBJD STATUS                         Dirty Blocks?     COUNT(*)
---------- ------------------------------ --------------- ----------
     15377 xcur                           Y                     2600
     15377 xcur                           N                     7408

no rows selected

NAME                                                    VALUE
-------------------------------------------------- ----------
DBWR checkpoint buffers written                         10422
DBWR checkpoints                                           30
DBWR parallel query checkpoint buffers written              0
DBWR tablespace checkpoint buffers written                  0
DBWR thread checkpoint buffers written                  10422
active txn count during cleanout                            0
cleanout - number of ktugct calls                        7400
cleanouts and rollbacks - consistent read gets              0
cleanouts only - consistent read gets                    7400
commit cleanouts                                         2654
commit cleanouts successfully completed                  2654
commit txn count during cleanout                         7400
deferred (CURRENT) block cleanout applications           2642
deferred CUR cleanouts (index blocks)                       0
immediate (CR) block cleanout applications               7400
immediate (CURRENT) block cleanout applications             7
immediate CR cleanouts (index blocks)                       0

17 rows selected.

SQL>
SQL> rem - now trigger a direct path read of the object. Object is large enough to want to do direct path IO
SQL> rem - based on size of the buffer cache and object in this example .. even though we only want first row of the table
SQL>
SQL> select /*+FULL(x)*/ count(c20) from user1.cf1_large x where rownum < 2; COUNT(C20) ----------          1 SQL>
SQL>
SQL> rem now check status of dirty blocks and confirm they have now been flushed and also the Tablespace checkpoint reported.
SQL> @check_status
SQL>
SQL> set echo off

      OBJD STATUS                         Dirty Blocks?     COUNT(*)
---------- ------------------------------ --------------- ----------
     15377 xcur                           N                    10008

EVENT                                    TOTAL_WAITS TIME_WAITED_MICRO
---------------------------------------- ----------- -----------------
enq: KO - fast object checkpoint                   1             78716

NAME                                                    VALUE
-------------------------------------------------- ----------
DBWR checkpoint buffers written                         13022
DBWR checkpoints                                           31
DBWR parallel query checkpoint buffers written              0
DBWR tablespace checkpoint buffers written               2600  <-- again in this case only the commit clean out blocks flushed
DBWR thread checkpoint buffers written                  10422
active txn count during cleanout                            0
cleanout - number of ktugct calls                        7400
cleanouts and rollbacks - consistent read gets              0
cleanouts only - consistent read gets                    7400
commit cleanouts                                         2654
commit cleanouts successfully completed                  2654
commit txn count during cleanout                         7400
deferred (CURRENT) block cleanout applications           2642
deferred CUR cleanouts (index blocks)                       0
immediate (CR) block cleanout applications               7400
immediate (CURRENT) block cleanout applications             7
immediate CR cleanouts (index blocks)                       0

17 rows selected.

About these ads

3 Comments »

  1. Hi, thanks for very good and clean bug(s) description ;)

    I have just one question regarding – let’s just say mitigation technique – wouldn’t it be possible in your opinion to avoid such I/O storms flooding whole storage array cache and causing spikes in LGWR commit times by partitioning the main table by date (especially as you mentioned you just delete old data every night – that way you could just DROP PARTITION?)? That way even if some devs/app would launch this very unfortunate buggy SELECT on whole table, then the check-pointing should occur – in worst case – sequentially on partition segment basis – one by one – at least in theory?

    Another thing… you wrote “I then issue a Full Table Scan of the table and regardless of the existence of ” rownum<2″ or not, because the size of the object means Oracle decides to do a “direct path read” … and if I'm reading it correctly it smells like in lack of "knowledge transfer" between CBO and handle_big_tables_using_directio() inside Oracle code… have you tried reproducing similar scenario but using bind variables like rownum<:B0 ?

    BTW: does this still reproduces on 11.2.0.3.4 ?

    -J.

    Comment by Jakub Wartak — 17/01/2013 @ 5:43 pm

    • Thanks for the feedback.

      You make a good point re Partitioning, but unfortunately that transactional system is not licenced for it. In one sense it does not really matter why we trigger the “direct path reads” (rownum used or not).. Someone will end up triggering at some point so we need to find a good way to reduce the number of these commit-cleanout dirty blocks. I have a couple of email threads on the go which I will update this note if I get more information and then I may be forced to break the transaction and see if I can de-stage the changes over a number of transactions.

      I have not yet tested 11.2.0.3.4 although not seen anything from Oracle Development to think it will be any difference (The statistic reporting will not have changed either based on conversations with Dev).

      Regards

      Nigel.

      Comment by Nigel Noble — 18/01/2013 @ 6:17 pm

  2. […] issue (And one I talked about in the past.. Strange statistic, large transactions, dirty buffers and direct path read ) highlight it would be really nice if Oracle made the percentage of commit-cleanout blocks touched […]

    Pingback by “enq: TX – contention” on SELECT with a large buffer cache and 2PC | Nigel Noble's Oracle Blog — 12/07/2013 @ 12:08 pm


RSS feed for comments on this post. TrackBack URI

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

The Silver is the New Black Theme Blog at WordPress.com.

Follow

Get every new post delivered to your Inbox.

Join 27 other followers

%d bloggers like this: