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.
Nigel Noble's Oracle Blog 
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
[…] 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