Delayed Block Cleanout

A query that reads datablocks that have been updated by a large DML (INSERT/UPDATE/DELETE) may well incur "delayed block cleanout". The commit operation of the DML does not involve clearing the ITL entries in each modified datablock but only marking the transaction in the undo slot entry as "COMMITTED" (plus, possibly, a few blocks being updated). Therefore, the next query (whether from the same database session OR from another database session) to read the datablock has to verify the ITL entries against the transaction in the undo segment and then "clean out" the ITL entry and the row marker in each datablock. This process of updating the datablock also generates redo.
The presence of the "Penalty" of delayed block cleanout is visible in the "cleanout %" statistics and also in the "consistent gets - examination" count [which is a subset of the "consistent gets" count].

This has implications in that large batch jobs that update very many datablocks and are able to exeute a COMMIT quickly actually cause subsequent jobs or queries against the same table to suffer this overhead.

You may not see "delayed block cleanout" when only a small set of datablocks are updated by a transaction.


This set of SQL commands and outputs below show how the *first* query against the table undergoing DML suffers this Penalty and the "cleanout %" and "consistent gets - examination" and "redo size" statistics are incremented (ie incurred) for this query but not the next query on the same datablocks.

I use with a table with 3.24million rows and run UPDATE, DELETE and INSERT operations against the table and identify the changes to these statistics which indicate delayed block cleanout.

SQL> select blocks,num_rows from user_tables where table_name = upper('test_d_b_c');

    BLOCKS   NUM_ROWS                                                                                                               
---------- ----------                                                                                                               
     47197    3242752                                                                                                               

SQL> REM Get the number of consistent gets -- the query has been run once ahead to parse it
SQL> SELECT COUNT(*) FROM TEST_D_B_C;

  COUNT(*)                                                                                                                          
----------                                                                                                                          
   3242752                                                                                                                          

SQL> @Report_select_Statistics
SQL> set echo off

Statistic                                                             Value                                                         
---------------------------------------------------------- ----------------                                                         
cleanout - number of ktugct calls                                         0                                                         
cleanouts and rollbacks - consistent read gets                            0                                                         
cleanouts only - consistent read gets                                     0                                                         
consistent changes                                                        0                                                         
consistent gets                                                      48,174                                                         
consistent gets - examination                                           498                                                         
db block changes                                                          4                                                         
db block gets                                                             3                                                         
redo entries                                                              2                                                         
redo size                                                               672                                                         
undo change vector size                                                 204                                                         
SQL> 
SQL> REM REM ########## Test for an UPDATE   ################ REM REM  ####################
SQL> REM Run an update on 60% (not all) of the rows
SQL> UPDATE TEST_D_B_C SET COL_1 = 'HKC_'||SUBSTR(COL_1,1,15) WHERE MOD(COL_4,10) > 3 ;

1945344 rows updated.

SQL> COMMIT;

Commit complete.

SQL> @Report_select_Statistics
SQL> set echo off

Statistic                                                             Value                                                         
---------------------------------------------------------- ----------------                                                         
cleanout - number of ktugct calls                                         0                                                         
cleanouts and rollbacks - consistent read gets                            0                                                         
cleanouts only - consistent read gets                                     0                                                         
consistent changes                                                        0                                                         
consistent gets                                                      95,395                                                         
consistent gets - examination                                           503                                                         
db block changes                                                  1,471,008                                                         
db block gets                                                       732,521                                                         
redo entries                                                        726,323                                                         
redo size                                                       340,420,260                                                         
undo change vector size                                         141,809,380                                                         
SQL> 
SQL> 
SQL> REM Now let's query the table
SQL> REM    The first execution will suffer delayed block cleanout
SQL> 
SQL> SELECT COUNT(*) FROM TEST_D_B_C;

  COUNT(*)                                                                                                                          
----------                                                                                                                          
   3242752                                                                                                                          

SQL> @Report_select_Statistics
SQL> set echo off

Statistic                                                             Value                                                         
---------------------------------------------------------- ----------------                                                         
cleanout - number of ktugct calls                                    46,969                                                         
cleanouts and rollbacks - consistent read gets                            0                                                         
cleanouts only - consistent read gets                                46,969                                                         
consistent changes                                                        0                                                         
consistent gets                                                     189,575                                                         
consistent gets - examination                                        47,472                                                         
db block changes                                                  1,517,977                                                         
db block gets                                                       732,521                                                         
redo entries                                                        773,293                                                         
redo size                                                       343,803,772                                                         
undo change vector size                                         141,809,380                                                         
SQL> 
SQL> SELECT COUNT(*) FROM TEST_D_B_C;

  COUNT(*)                                                                                                                          
----------                                                                                                                          
   3242752                                                                                                                          

SQL> @Report_select_Statistics
SQL> set echo off

Statistic                                                             Value                                                         
---------------------------------------------------------- ----------------                                                         
cleanout - number of ktugct calls                                    46,969                                                         
cleanouts and rollbacks - consistent read gets                            0                                                         
cleanouts only - consistent read gets                                46,969                                                         
consistent changes                                                        0                                                         
consistent gets                                                     236,786                                                         
consistent gets - examination                                        47,472                                                         
db block changes                                                  1,517,977                                                         
db block gets                                                       732,521                                                         
redo entries                                                        773,293                                                         
redo size                                                       343,803,772                                                         
undo change vector size                                         141,809,380                                                         
SQL> 
SQL> 
SQL> REM REM ########## Test for a DELETE   ################ REM REM  ####################
SQL> REM  Test for a DELETE
SQL> DELETE TEST_D_B_C WHERE MOD(COL_4,5) > 3;

648640 rows deleted.

SQL> COMMIT;

Commit complete.

SQL> @Report_select_Statistics
SQL> set echo off

Statistic                                                             Value                                                         
---------------------------------------------------------- ----------------                                                         
cleanout - number of ktugct calls                                    46,969                                                         
cleanouts and rollbacks - consistent read gets                            0                                                         
cleanouts only - consistent read gets                                46,969                                                         
consistent changes                                                        0                                                         
consistent gets                                                     284,451                                                         
consistent gets - examination                                        47,486                                                         
db block changes                                                  2,870,813                                                         
db block gets                                                     1,465,003                                                         
redo entries                                                      1,458,221                                                         
redo size                                                       586,670,260                                                         
undo change vector size                                         292,754,836                                                         
SQL> 
SQL> REM Now let's query the table
SQL> REM    The first execution will suffer delayed block cleanout
SQL> 
SQL> SELECT COUNT(*) FROM TEST_D_B_C;

  COUNT(*)                                                                                                                          
----------                                                                                                                          
   2594112                                                                                                                          

SQL> @Report_select_Statistics
SQL> set echo off

Statistic                                                             Value                                                         
---------------------------------------------------------- ----------------                                                         
cleanout - number of ktugct calls                                    56,180                                                         
cleanouts and rollbacks - consistent read gets                            0                                                         
cleanouts only - consistent read gets                                56,180                                                         
consistent changes                                                        0                                                         
consistent gets                                                     340,873                                                         
consistent gets - examination                                        56,697                                                         
db block changes                                                  2,880,024                                                         
db block gets                                                     1,465,003                                                         
redo entries                                                      1,467,432                                                         
redo size                                                       587,334,024                                                         
undo change vector size                                         292,754,836                                                         
SQL> 
SQL> SELECT COUNT(*) FROM TEST_D_B_C;

  COUNT(*)                                                                                                                          
----------                                                                                                                          
   2594112                                                                                                                          

SQL> @Report_select_Statistics
SQL> set echo off

Statistic                                                             Value                                                         
---------------------------------------------------------- ----------------                                                         
cleanout - number of ktugct calls                                    56,180                                                         
cleanouts and rollbacks - consistent read gets                            0                                                         
cleanouts only - consistent read gets                                56,180                                                         
consistent changes                                                        0                                                         
consistent gets                                                     388,084                                                         
consistent gets - examination                                        56,697                                                         
db block changes                                                  2,880,024                                                         
db block gets                                                     1,465,003                                                         
redo entries                                                      1,467,432                                                         
redo size                                                       587,334,024                                                         
undo change vector size                                         292,754,836                                                         
SQL> 
SQL> 
SQL> REM REM ########## Test for a INSERT   ################ REM REM  ####################
SQL> REM Test for an INSERT
SQL> INSERT INTO TEST_D_B_C SELECT * FROM TEST_D_B_C_BAK WHERE MOD(COL_4,5) > 3;

648640 rows created.

SQL> COMMIT;

Commit complete.

SQL> @Report_select_Statistics
SQL> set echo off

Statistic                                                             Value                                                         
---------------------------------------------------------- ----------------                                                         
cleanout - number of ktugct calls                                    65,255                                                         
cleanouts and rollbacks - consistent read gets                            0                                                         
cleanouts only - consistent read gets                                56,180                                                         
consistent changes                                                        0                                                         
consistent gets                                                     453,419                                                         
consistent gets - examination                                        65,810                                                         
db block changes                                                  2,936,433                                                         
db block gets                                                     1,532,712                                                         
redo entries                                                      1,506,633                                                         
redo size                                                       659,399,228                                                         
undo change vector size                                         295,378,592                                                         
SQL> 
SQL> REM Now let's query the table
SQL> REM    The first execution will suffer delayed block cleanout
SQL> 
SQL> SELECT COUNT(*) FROM TEST_D_B_C;

  COUNT(*)                                                                                                                          
----------                                                                                                                          
   3242752                                                                                                                          

SQL> @Report_select_Statistics
SQL> set echo off

Statistic                                                             Value                                                         
---------------------------------------------------------- ----------------                                                         
cleanout - number of ktugct calls                                    72,839                                                         
cleanouts and rollbacks - consistent read gets                            0                                                         
cleanouts only - consistent read gets                                63,764                                                         
consistent changes                                                        0                                                         
consistent gets                                                     508,214                                                         
consistent gets - examination                                        73,394                                                         
db block changes                                                  2,944,017                                                         
db block gets                                                     1,532,712                                                         
redo entries                                                      1,514,217                                                         
redo size                                                       659,945,320                                                         
undo change vector size                                         295,378,592                                                         
SQL> 
SQL> SELECT COUNT(*) FROM TEST_D_B_C;

  COUNT(*)                                                                                                                          
----------                                                                                                                          
   3242752                                                                                                                          

SQL> @Report_select_Statistics
SQL> set echo off

Statistic                                                             Value                                                         
---------------------------------------------------------- ----------------                                                         
cleanout - number of ktugct calls                                    72,839                                                         
cleanouts and rollbacks - consistent read gets                            0                                                         
cleanouts only - consistent read gets                                63,764                                                         
consistent changes                                                        0                                                         
consistent gets                                                     555,425                                                         
consistent gets - examination                                        73,394                                                         
db block changes                                                  2,944,017                                                         
db block gets                                                     1,532,712                                                         
redo entries                                                      1,514,217                                                         
redo size                                                       659,945,320                                                         
undo change vector size                                         295,378,592                                                         
SQL> 

As you can see "cleanout - number of ktugct calls" and "cleanouts only - consistent read gets" are incremented as with "consistent gets - examination". [Remember that "consistent gets - examination" count is *included* in "consistent gets" count]. Also, "redo entries" and "redo size" are incremented. These occur for the first query against the modified datablocks.
NOTE : This table [TEST_D_B_C] does NOT have any indexes so "consistent gets - examination" does NOT reflect reads on index blocks [root blocks or otherwise]. {google might show a few references indicating the "consistent gets - examination" occurs for index blocks but that isn't the only case for this statistic}.


The above test was on 10.2.0.1 I have had similar results on 10.2.0.2

However, on 10.2.0.4 I have had a very surprisingly large number of "consistent gets - examination" {exceeding 1.9million} for the UPDATE itself [testing with both ASSM and MSSM], which I cannot explain yet. The "consistent gets - examination" count for the "delayed block cleanout" effect on the first query is still consistent. However, I haven't published the 10.2.0.4 numbers because of the 1.9million "consistent gets - examination" in the UPDATE. That is something I have to investigate.

Relational Theory and SQL

Here's an interesting thread on Oracle-L developing on how well should SQL practitioners know Relational Theory, Relational Calculus etc.

ASSM or MSSM ? -- DELETE and INSERT

Continuing my first set of tests, I now look at Bug#4475314 which shows that an INSERT that follows a DELETE without an intervening COMMIT can suffer much higher 'current gets'. The teste case in that Bug actually shows a very significant difference between the DELETE-COMMIT-INSERT and DELETE-INSERT runs.

So, here I ran similar SQLs as in my first set of tests :

MSSM :

drop tablespace mssm_tbs including contents and datafiles;
create tablespace mssm_tbs
datafile '/oracle_fs/Databases/ORT24FS/mssm01.dbf' size 1000M
extent management local autoallocate segment space management manual;

undefine  sid
col mysid new_value sid
select distinct sid mysid from V$mystat ;


alter session set tracefile_identifier='run_delete_insert_tests_mssm';
alter session set events '10046 trace name context forever, level 8';

alter table source_table cache;
select /*+ FULL (s) */ count(*) from source_table s;

create table target_table_mssm tablespace mssm_tbs as select * from source_table where 1=2;

insert /* first_mssm_insert */ into target_table_mssm select * from source_table;
commit;

delete /* first_mssm_delete */ target_table_mssm;

insert /* reinsert_mssm_insert */ into target_table_mssm select * from source_table;
commit;

create index target_table_mssm_ndx on target_table_mssm(object_id) tablespace mssm_tbs;

delete /* indexed_mssm_delete */ target_table_mssm;

insert /* indexed_mssm_insert */ into target_table_mssm select * from source_table;
commit;

ASSM :

drop tablespace assm_tbs including contents and datafiles;
create tablespace assm_tbs
datafile '/oracle_fs/Databases/ORT24FS/assm01.dbf' size 1000M
extent management local autoallocate segment space management auto;

undefine  sid
col mysid new_value sid
select distinct sid mysid from V$mystat ;


alter session set tracefile_identifier='run_delete_insert_tests_assm';
alter session set events '10046 trace name context forever, level 8';

alter table source_table cache;
select /*+ FULL (s) */ count(*) from source_table s;

create table target_table_assm tablespace assm_tbs as select * from source_table where 1=2;

insert /* first_assm_insert */ into target_table_assm select * from source_table;
commit;

delete /* first_assm_delete */ target_table_assm;

insert /* reinsert_assm_insert */ into target_table_assm select * from source_table;
commit;

create index target_table_assm_ndx on target_table_assm(object_id) tablespace assm_tbs;

delete /* indexed_assm_delete */ target_table_assm;

insert /* indexed_assm_insert */ into target_table_assm select * from source_table;
commit;

Rather than repeating the normal INSERT statements (which you can also see in my first set of tests), I will emphasise the INSERTs that followed DELETEs (without intervening COMMITs) :

MSSM :

delete /* first_mssm_delete */ target_table_mssm


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          1          0           0
Execute      1      6.27      12.47          0       5206     326203      303666
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      6.27      12.48          0       5207     326203      303666

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  DELETE  TARGET_TABLE_MSSM (cr=5206 pr=0 pw=0 time=12478853 us)
 303666   TABLE ACCESS FULL TARGET_TABLE_MSSM (cr=4857 pr=0 pw=0 time=911106 us)

insert /* reinsert_mssm_insert */ into target_table_mssm select * from
  source_table


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      1.00       1.65          0      12367      17122      303666
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      1.01       1.65          0      12367      17122      303666

Rows     Row Source Operation
-------  ---------------------------------------------------
 303666  TABLE ACCESS FULL SOURCE_TABLE (cr=4193 pr=0 pw=0 time=607452 us)

delete /* indexed_mssm_delete */ target_table_mssm


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.01          0          2          0           0
Execute      1     11.01      16.14        671       4325    1243651      303666
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2     11.02      16.16        671       4327    1243651      303666

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  DELETE  TARGET_TABLE_MSSM (cr=4325 pr=671 pw=0 time=16140802 us)
 303666   TABLE ACCESS FULL TARGET_TABLE_MSSM (cr=4325 pr=0 pw=0 time=1518587 us)

insert /* indexed_mssm_insert */ into target_table_mssm select * from
  source_table


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      3.09       7.54         63      16018      78398      303666
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      3.09       7.54         63      16018      78398      303666

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 64

Rows     Row Source Operation
-------  ---------------------------------------------------
 303666  TABLE ACCESS FULL SOURCE_TABLE (cr=4193 pr=0 pw=0 time=911112 us) 

ASSM :

delete /* first_assm_delete */ target_table_assm


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          1          0           0
Execute      1      7.04      14.30          0       4880     337910      303666
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      7.04      14.30          0       4881     337910      303666

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  DELETE  TARGET_TABLE_ASSM (cr=4880 pr=0 pw=0 time=14305853 us)
 303666   TABLE ACCESS FULL TARGET_TABLE_ASSM (cr=4880 pr=0 pw=0 time=934334 us)

insert /* reinsert_assm_insert */ into target_table_assm select * from
  source_table


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      1.50       2.02          0      21396      52236      303666
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      1.50       2.02          0      21396      52236      303666

Rows     Row Source Operation
-------  ---------------------------------------------------
 303666  TABLE ACCESS FULL SOURCE_TABLE (cr=4193 pr=0 pw=0 time=911120 us)

delete /* indexed_assm_delete */ target_table_assm


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.02          0          2          0           0
Execute      1     14.84      22.03        672       4502    1258653      303666
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2     14.84      22.06        672       4504    1258653      303666

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  DELETE  TARGET_TABLE_ASSM (cr=4988 pr=673 pw=0 time=22090153 us)
 303666   TABLE ACCESS FULL TARGET_TABLE_ASSM (cr=4364 pr=0 pw=0 time=1214785 us)

insert /* indexed_assm_insert */ into target_table_assm select * from
  source_table


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      2.92       5.45          1      26743     117158      303666
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      2.92       5.45          1      26743     117158      303666

Rows     Row Source Operation
-------  ---------------------------------------------------
 303666  TABLE ACCESS FULL SOURCE_TABLE (cr=4193 pr=0 pw=0 time=911153 us) 

The INSERT operations in the ASSM tablespace are more expensive.

                           MSSM             ASSM
Delete
 Consistent Gets            5,206           4,880
 Current Gets             326,203         337,910
 CPU Used (seconds)          6.27            7.04
Insert after Delete
 Consistent Gets           12,367          21,396
 Current Gets              17,122          52,236
 CPU Used (seconds)          1.00            1.50

Delete with Index present
 Consistent Gets            4,325           4,502
 Current Gets           1,243,651       1,258,653
 CPU Used (seconds)         11.01           14.84
Insert after this Delete
 Consistent Gets           16,018          26,743
 Current Gets              78,398         117,158
 CPU Used (seconds)          3.09            2.92

Think carefully before using ASSM for segments that
a) Undergo large Inserts OR Deletes and Inserts
b) Are executed by batch jobs, not multiple,concurrent, online users.