Martins Blog

Trying to explain complex things in simple terms

Understanding enhancements to block cleanouts in Exadata part 1

Posted by Martin Bach on February 23, 2015

Travel time is writing time and I have the perfect setting for a techie post. Actually I got quite excited about the subject causing the article to get a bit longer than initially anticipated. In this part you can read about block cleanouts when using buffered I/O. The next part will show how this works using direct path reads and Smart Scans.

The article ultimately aims at describing the enhancements Exadata brings to the table for direct path reads and delayed block cleanouts. Delayed block cleanouts are described in Jonathan Lewis’s “Oracle Core”, and in one of his blog posts, so here’s just a summary.

The delayed block cleanout

In a nutshell Oracle’s database writer (the process persisting your transactions to disk) is free to write blocks to disk in batches when it has to be done. A commit on its own won’t trigger a write of dirty (or modified) block to disk. If it were to trigger the write, the commit-time would be proportional to the number of blocks affected by the last transaction. The commit command however completes very quickly regardless of how much data has been affected. Unlike a rollback … It is entirely possible that a block modified by a transaction is written to disk before the transaction has been completed. A little later, once the commit has been acknowledged by Oracle there is no process that would read the blocks back into the buffer cache and clear them out-this happens later. It would also be quite inefficient to do so.

Defining “clean”

Now when database writer writes to disk it is possible that the block just written has an active transaction recorded in its header. You can see this by dumping a block with an active transaction – the ITL in the header will reference the XID, UBA and the number of rows affected plus other information. The individual rows that are part of the transaction have their lock byte set as you can see in the row directory. The number in the lb field refers back to an ITL you see further up in the block dump (don’t worry I’ll show you an example shortly).

What happened in Oracle before direct path reads became a lot more common is this:

  • A user starts a transaction, for example by updating a large portion of the table
  • In the meantime the database writer flushes some blocks to disk, including some of the ones affected by the transaction.
  • The user commits a transaction
  • The next user queries the block (let’s assume it is not in the buffer cache)
  • The second session’s foreground process reads the block
    • Realises that it has an active transaction recorded in it
    • Checks if that transaction is still active
    • And clears the block out if not
  • The block with a valid CR image is now in the buffer cache

Huh?

Sounds too abstract-I agree? Let’s have an example.

SQL> select table_name,num_rows,compression,partitioned from tabs
  2  where table_name = 'T1_100k';

TABLE_NAME                       NUM_ROWS COMPRESS PAR
------------------------------ ---------- -------- ---
T1_100K                            500000 DISABLED NO

SQL> update T1_100k set state = 'MODIFIED';

5000000 rows updated.

An easy way to simulate the flushing of blocks to disk is a slightly brute-force approach of flushing the buffer cache. Only recommended in the lab, really. Let’s have a look at what the block looks like:

SQL> select dbms_rowid.rowid_block_number(rowid), dbms_rowid.rowid_relative_fno(rowid)
  2  from t1_100k where rownum < 11;

DBMS_ROWID.ROWID_BLOCK_NUMBER(ROWID) DBMS_ROWID.ROWID_RELATIVE_FNO(ROWID)
------------------------------------ ------------------------------------
                             3940811                                    5
                             3940811                                    5
                             3940811                                    5
                             3940811                                    5
                             3940811                                    5
                             3940811                                    5
                             3940812                                    5
                             3940812                                    5
                             3940812                                    5
                             3940812                                    5

10 rows selected.

Elapsed: 00:00:00.01
SQL> alter system dump datafile 5 block 3940811;

System altered.

Elapsed: 00:00:00.01
SQL> select value from v$diag_info where name like 'Default%';

VALUE
---------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/dbm01/dbm011/trace/dbm011_ora_94351.trc

Elapsed: 00:00:00.02

The block dump for block 3940811 on datafile 5 (users tablespace) is now in that trace file:

Block header dump:  0x017c21cb
 Object id on Block? Y
 seg/obj: 0x12a13  csc: 0x00.2191ff7  itc: 3  flg: E  typ: 1 - DATA
     brn: 0  bdba: 0x17c21c8 ver: 0x01 opc: 0
     inc: 0  exflg: 0

 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0xffff.000.00000000  0x00000000.0000.00  C---    0  scn 0x0000.02191d10
0x02   0x0009.005.00002575  0x0003688a.0ef1.1f  ----    6  fsc 0x0000.00000000
0x03   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000
bdba: 0x017c21cb
data_block_dump,data header at 0x7f026361707c
===============
tsiz: 0x1f80
hsiz: 0x1e
pbl: 0x7f026361707c
     76543210
flag=--------
ntab=1
nrow=6
...
0xe:pti[0]      nrow=6  offs=0
0x12:pri[0]     offs=0x1b75
0x14:pri[1]     offs=0x176a
0x16:pri[2]     offs=0x135f
0x18:pri[3]     offs=0xf54
0x1a:pri[4]     offs=0xb49
0x1c:pri[5]     offs=0x73e
block_row_dump:
tab 0, row 0, @0x1b75
tl: 1035 fb: --H-FL-- lb: 0x2  cc: 6
col  0: [ 2]  c1 02
col  1: [999]
 31 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20
 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20
...

The significant pieces of information here are in the ITL (interested transaction list) and the lock byte set, pointing to the second ITL entry. The absence of flags for ITL #2 indicates the transaction is ongoing (you can see this in v$transaction-this is a lab environment, in real databases you’d see more than 1 active transaction):

SQL> select xidusn, xidslot, xidsqn, status, start_scn from v$transaction;

    XIDUSN    XIDSLOT     XIDSQN STATUS            START_SCN
---------- ---------- ---------- ---------------- ----------
         9          5       9589 ACTIVE             35200741

This is indeed the transaction that is referenced in v$transaction and the ITL 0x02 above (9589 is decimal for 2575 in hexadecimal notation, 9 and 5 don’t need converting to decimal numbers). If you are curious now about some more internals then you might find this post by Arup Nanda interesting.

Now what happens if another session queries the table? Since the query in session 1 has not yet committed the changes in it must not be seen by any other session (that would be a dirty read otherwise. We do not use dirty reads in Oracle RDBMS). So to give the user a consistent view of the data the block must be rolled back. Before the test I made sure there wasn’t a block in the buffer cache for the object in question:

SQL> select count(*), inst_id, status from gv$bh where objd =
  2   (select data_object_id from dba_objects where object_name = 'T1_100K')
  3  group by inst_id, status;

  COUNT(*)    INST_ID STATUS
---------- ---------- ----------
    524327          1 free

Let’s test:

SQL> @mystats start

SQL> select /* test004 */ count(*) from t1_100k;

  COUNT(*)
----------
    500000

Elapsed: 00:00:13.96

@mystats stop t=1

==========================================================================================
MyStats report : 22-FEB-2015 08:42:09
==========================================================================================


------------------------------------------------------------------------------------------
1. Summary Timings
------------------------------------------------------------------------------------------

Type    Statistic Name                                                               Value
------  ----------------------------------------------------------------  ----------------
TIMER   snapshot interval (seconds)                                                  35.57
TIMER   CPU time used (seconds)                                                       3.21


------------------------------------------------------------------------------------------
2. Statistics Report
------------------------------------------------------------------------------------------

Type    Statistic Name                                                               Value
------  ----------------------------------------------------------------  ----------------
STAT    CPU used by this session                                                       327
STAT    CPU used when call started                                                     327
STAT    CR blocks created                                                           83,334
STAT    DB time                                                                      1,401
STAT    Requests to/from client                                                         16
STAT    SQL*Net roundtrips to/from client                                               16
STAT    active txn count during cleanout                                            83,334
STAT    buffer is not pinned count                                                       2
STAT    bytes received via SQL*Net from client                                      13,279
STAT    bytes sent via SQL*Net to client                                             5,106
STAT    calls to get snapshot scn: kcmgss                                              758
STAT    calls to kcmgas                                                             83,332
STAT    calls to kcmgcs                                                                 30
STAT    cell flash cache read hits                                                   8,045
STAT    cell physical IO interconnect bytes                                    748,576,768
STAT    change write time                                                               48
STAT    cleanout - number of ktugct calls                                           83,334
STAT    cleanouts and rollbacks - consistent read gets                              83,334
STAT    consistent changes                                                         591,717
STAT    consistent gets                                                            757,980
STAT    consistent gets examination                                                674,254
STAT    consistent gets examination (fastpath)                                      83,337
STAT    consistent gets from cache                                                 757,980
STAT    consistent gets pin                                                         83,726
STAT    consistent gets pin (fastpath)                                              83,055
STAT    data blocks consistent reads - undo records applied                        590,917
STAT    db block changes                                                            84,134
STAT    db block gets                                                                2,301
STAT    db block gets from cache                                                     2,301
STAT    enqueue releases                                                                 4
STAT    enqueue requests                                                                 4
STAT    execute count                                                                   13
STAT    file io wait time                                                       11,403,214
STAT    free buffer requested                                                      174,766
STAT    gc local grants                                                            174,713
STAT    global enqueue gets sync                                                        43
STAT    global enqueue releases                                                         41
STAT    heap block compress                                                          4,549
STAT    hot buffers moved to head of LRU                                                 4
STAT    immediate (CR) block cleanout applications                                  83,334
STAT    index fetch by key                                                               1
STAT    lob writes                                                                     375
STAT    lob writes unaligned                                                           375
STAT    logical read bytes from cache                                        6,228,221,952
STAT    messages sent                                                                    9
STAT    non-idle wait count                                                         17,446
STAT    non-idle wait time                                                           1,141
STAT    opened cursors cumulative                                                       13
STAT    parse count (hard)                                                               1
STAT    parse count (total)                                                             13
STAT    physical read IO requests                                                    8,715
STAT    physical read bytes                                                    748,576,768
STAT    physical read requests optimized                                             8,045
STAT    physical read total IO requests                                              8,715
STAT    physical read total bytes                                              748,576,768
STAT    physical read total bytes optimized                                     65,904,640
STAT    physical read total multi block requests                                       654
STAT    physical reads                                                              91,379
STAT    physical reads cache                                                        91,379
STAT    physical reads cache prefetch                                               82,664
STAT    recursive calls                                                              1,985
STAT    recursive cpu usage                                                              6
STAT    redo entries                                                                84,005
STAT    redo entries for lost write detection                                          671
STAT    redo size                                                                9,016,740
STAT    redo size for lost write detection                                       3,016,296
STAT    redo subscn max counts                                                      83,334
STAT    rows fetched via callback                                                        1
STAT    session cursor cache count                                                       4
STAT    session cursor cache hits                                                        9
STAT    session logical reads                                                      760,281
STAT    session pga memory                                                         -65,536
STAT    session uga memory                                                          65,488
STAT    session uga memory max                                                     148,312
STAT    shared hash latch upgrades - no wait                                         8,218
STAT    table fetch by rowid                                                             1
STAT    table scan blocks gotten                                                    83,334
STAT    table scan disk non-IMC rows gotten                                        500,000
STAT    table scan rows gotten                                                     500,000
STAT    table scans (short tables)                                                       1
STAT    temp space allocated (bytes)                                             2,097,152
STAT    user I/O wait time                                                           1,141
STAT    user calls                                                                      22
STAT    workarea executions - optimal                                                    1
STAT    workarea memory allocated                                                      -43


------------------------------------------------------------------------------------------
3. About
------------------------------------------------------------------------------------------
- MyStats v2.01 by Adrian Billington (http://www.oracle-developer.net)
- Based on the SNAP_MY_STATS utility by Jonathan Lewis

==========================================================================================
End of report
==========================================================================================

I am using Adrian Billington’s mystats script here which I can only recommend to you-it’s very decent (and that’s an understatement). In the example above it took two snapshots and calculated the change of the session counters in v$mystat during the query execution. Have a look at the cleanout% statistics here! These are the block cleanouts. As this generates redo you can see that recorded here too. This is a tricky interview question: can a select generate redo? Yes sure can! There is also a fair amount of physical I/O going on. After all the buffer cache was empty.

The second execution of the query completes a lot faster due to the absence of physical I/O. Nevertheless, the session has to clean out all these blocks and perform consistent read processing again (remember the transaction is still uncommitted as seen in active txn%):

SQL> select count(*) from t1_100k;

  COUNT(*)
----------
    500000

Elapsed: 00:00:01.76

SQL> @mystats stop t=1

==========================================================================================
MyStats report : 22-FEB-2015 08:42:59
==========================================================================================


------------------------------------------------------------------------------------------
1. Summary Timings
------------------------------------------------------------------------------------------

Type    Statistic Name                                                               Value
------  ----------------------------------------------------------------  ----------------
TIMER   snapshot interval (seconds)                                                   8.55
TIMER   CPU time used (seconds)                                                       1.75


------------------------------------------------------------------------------------------
2. Statistics Report
------------------------------------------------------------------------------------------

Type    Statistic Name                                                               Value
------  ----------------------------------------------------------------  ----------------
STAT    CPU used by this session                                                       181
STAT    CPU used when call started                                                     181
STAT    CR blocks created                                                           83,334
STAT    DB time                                                                        183
STAT    Requests to/from client                                                         16
STAT    SQL*Net roundtrips to/from client                                               16
STAT    active txn count during cleanout                                            83,334
STAT    buffer is not pinned count                                                       2
STAT    bytes received via SQL*Net from client                                      13,280
STAT    bytes sent via SQL*Net to client                                             5,177
STAT    calls to get snapshot scn: kcmgss                                              757
STAT    calls to kcmgas                                                             83,331
STAT    calls to kcmgcs                                                                 30
STAT    change write time                                                               28
STAT    cleanout - number of ktugct calls                                           83,334
STAT    cleanouts and rollbacks - consistent read gets                              83,334
STAT    consistent changes                                                         591,708
STAT    consistent gets                                                            757,980
STAT    consistent gets examination                                                674,254
STAT    consistent gets examination (fastpath)                                      83,337
STAT    consistent gets from cache                                                 757,980
STAT    consistent gets pin                                                         83,726
STAT    consistent gets pin (fastpath)                                              83,726
STAT    cursor authentications                                                           1
STAT    data blocks consistent reads - undo records applied                        590,917
STAT    db block changes                                                            84,125
STAT    db block gets                                                                2,895
STAT    db block gets from cache                                                     2,895
STAT    execute count                                                                   13
STAT    free buffer requested                                                       83,382
STAT    global enqueue gets sync                                                        38
STAT    global enqueue releases                                                         36
STAT    heap block compress                                                          4,549
STAT    immediate (CR) block cleanout applications                                  83,334
STAT    index fetch by key                                                               1
STAT    lob writes                                                                     375
STAT    lob writes unaligned                                                           375
STAT    logical read bytes from cache                                        6,233,088,000
STAT    messages sent                                                                    7
STAT    non-idle wait count                                                             16
STAT    opened cursors cumulative                                                       13
STAT    parse count (total)                                                             13
STAT    recursive calls                                                              1,982
STAT    recursive cpu usage                                                              6
STAT    redo entries                                                                83,334
STAT    redo size                                                                6,000,400
STAT    rows fetched via callback                                                        1
STAT    session cursor cache hits                                                       12
STAT    session logical reads                                                      760,875
STAT    session pga memory                                                      -1,769,472
STAT    session uga memory                                                      -1,858,472
STAT    shared hash latch upgrades - no wait                                           524
STAT    table fetch by rowid                                                             1
STAT    table scan blocks gotten                                                    83,334
STAT    table scan disk non-IMC rows gotten                                        500,000
STAT    table scan rows gotten                                                     500,000
STAT    table scans (short tables)                                                       1
STAT    user calls                                                                      22
STAT    workarea executions - optimal                                                    1
STAT    workarea memory allocated                                                      -83


------------------------------------------------------------------------------------------
3. About
------------------------------------------------------------------------------------------
- MyStats v2.01 by Adrian Billington (http://www.oracle-developer.net)
- Based on the SNAP_MY_STATS utility by Jonathan Lewis

==========================================================================================
End of report
==========================================================================================

I should have mentioned that these 2 examples were executed on an X2-2 quarter rack. To prevent Exadata from applying some clever optimisations I specifically disabled direct path reads and turned off Exadata features. Here is the view from the buffer cache again:

SQL> select count(*), inst_id, status from gv$bh where objd =
  2   (select data_object_id from dba_objects where object_name = 'T1_100K')
  3  group by inst_id, status;

  COUNT(*)    INST_ID STATUS
---------- ---------- ----------
    351704          1 free
         1          1 scur
     83334          1 xcur
     83334          1 cr

4 rows selected.

For each subsequent execution of the select statement consistent read processing has to be conducted. The number of CR blocks in the buffer cache will increase. For the third execution I can see the following:

SQL> r
  1  select count(*), inst_id, status from gv$bh where objd =
  2   (select data_object_id from dba_objects where object_name = 'T1_100K')
  3* group by inst_id, status

  COUNT(*)    INST_ID STATUS
---------- ---------- ----------
    267526          1 free
         1          1 scur
     83334          1 xcur
    166668          1 cr

4 rows selected.

Things improve when the transaction commits.

The impact of a commit

What about a commit now? Committing in session 1 and running the query again in session 2 shows a very good response time. Please remember that I forced buffered reads. The next part deals with this case when using direct path reads instead (those are not buffered). The segment size would have qualified for direct path reads otherwise.

SQL> select /* test004 */ count(*) from t1_100k;

  COUNT(*)
----------
    500000

Elapsed: 00:00:00.18

==========================================================================================
MyStats report : 22-FEB-2015 09:40:08
==========================================================================================


------------------------------------------------------------------------------------------
1. Summary Timings
------------------------------------------------------------------------------------------

Type    Statistic Name                                                               Value
------  ----------------------------------------------------------------  ----------------
TIMER   snapshot interval (seconds)                                                  19.73
TIMER   CPU time used (seconds)                                                       0.18


------------------------------------------------------------------------------------------
2. Statistics Report
------------------------------------------------------------------------------------------

Type    Statistic Name                                                               Value
------  ----------------------------------------------------------------  ----------------
STAT    CPU used by this session                                                        25
STAT    CPU used when call started                                                      25
STAT    DB time                                                                         25
STAT    Heatmap SegLevel - Full Table Scan                                               1
STAT    Requests to/from client                                                         16
STAT    SQL*Net roundtrips to/from client                                               16
STAT    buffer is not pinned count                                                       2
STAT    bytes received via SQL*Net from client                                      13,280
STAT    bytes sent via SQL*Net to client                                             5,107
STAT    calls to get snapshot scn: kcmgss                                              757
STAT    calls to kcmgcs                                                                 30
STAT    consistent changes                                                             800
STAT    consistent gets                                                             83,729
STAT    consistent gets examination                                                      3
STAT    consistent gets examination (fastpath)                                           3
STAT    consistent gets from cache                                                  83,729
STAT    consistent gets pin                                                         83,726
STAT    consistent gets pin (fastpath)                                              83,726
STAT    db block changes                                                               800
STAT    db block gets                                                                2,301
STAT    db block gets from cache                                                     2,301
STAT    enqueue releases                                                                 3
STAT    enqueue requests                                                                 3
STAT    execute count                                                                   13
STAT    free buffer requested                                                           53
STAT    global enqueue gets sync                                                        39
STAT    global enqueue releases                                                         37
STAT    index fetch by key                                                               1
STAT    lob writes                                                                     375
STAT    lob writes unaligned                                                           375
STAT    logical read bytes from cache                                          704,757,760
STAT    no work - consistent read gets                                              83,334
STAT    non-idle wait count                                                             16
STAT    opened cursors cumulative                                                       13
STAT    parse count (total)                                                             13
STAT    recursive calls                                                              1,984
STAT    recursive cpu usage                                                              7
STAT    rows fetched via callback                                                        1
STAT    session cursor cache count                                                       4
STAT    session cursor cache hits                                                       10
STAT    session logical reads                                                       86,030
STAT    session pga memory                                                          65,536
STAT    session pga memory max                                                      65,536
STAT    session uga memory                                                          65,488
STAT    session uga memory max                                                     148,312
STAT    shared hash latch upgrades - no wait                                           525
STAT    table fetch by rowid                                                             1
STAT    table scan blocks gotten                                                    83,334
STAT    table scan disk non-IMC rows gotten                                        500,000
STAT    table scan rows gotten                                                     500,000
STAT    table scans (short tables)                                                       1
STAT    temp space allocated (bytes)                                             2,097,152
STAT    user calls                                                                      22
STAT    workarea executions - optimal                                                    1
STAT    workarea memory allocated                                                      -40


------------------------------------------------------------------------------------------
3. About
------------------------------------------------------------------------------------------
- MyStats v2.01 by Adrian Billington (http://www.oracle-developer.net)
- Based on the SNAP_MY_STATS utility by Jonathan Lewis

==========================================================================================
End of report
==========================================================================================

Access to blocks in the buffer cache is quick! There was no need to clean out any blocks anymore. The fastest way to do something is indeed not having to do it at all. Mind you, the block on disk still has the active transaction recorded!

SQL> alter system dump datafile 5 block 3940811;

System altered.

Elapsed: 00:00:00.01
SQL> select value from v$diag_info where name like 'Default%';

VALUE
------------------------------------------------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/dbm01/dbm011/trace/dbm011_ora_100297.trc

SQL> exit

$ vi /u01/app/oracle/diag/rdbms/dbm01/dbm011/trace/dbm011_ora_100297.trc

Block header dump:  0x017c21cb
 Object id on Block? Y
 seg/obj: 0x12a13  csc: 0x00.2317620  itc: 3  flg: E  typ: 1 - DATA
     brn: 0  bdba: 0x17c21c8 ver: 0x01 opc: 0
     inc: 0  exflg: 0

 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0xffff.000.00000000  0x00000000.0000.00  C---    0  scn 0x0000.02191d10
0x02   0x0009.005.00002575  0x0003688a.0ef1.1f  --U-    6  fsc 0x0000.0232cfca
0x03   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000
bdba: 0x017c21cb
data_block_dump,data header at 0x7fc9f3cb407c
...

$ grep lb -B1 /u01/app/oracle/diag/rdbms/dbm01/dbm011/trace/dbm011_ora_100297.trc
tab 0, row 0, @0x1b75
tl: 1035 fb: --H-FL-- lb: 0x2  cc: 6
--
tab 0, row 1, @0x176a
tl: 1035 fb: --H-FL-- lb: 0x2  cc: 6
--
tab 0, row 2, @0x135f
tl: 1035 fb: --H-FL-- lb: 0x2  cc: 6
--
tab 0, row 3, @0xf54
tl: 1035 fb: --H-FL-- lb: 0x2  cc: 6
--
tab 0, row 4, @0xb49
tl: 1035 fb: --H-FL-- lb: 0x2  cc: 6
--
tab 0, row 5, @0x73e
tl: 1035 fb: --H-FL-- lb: 0x2  cc: 6
--

The transaction recorded in the ITL slot 2 is gone though:

SQL> select xidusn, xidslot, xidsqn, status, start_scn from v$transaction
  2  where xidusn = 9 and xidslot = 5 and xidsqn = 9589;

no rows selected

Did you notice the Flag in the second ITL entry? That wasn’t there before. It indicates a fast commit according to Core Oracle by Jonathan Lewis.

Summary

Block cleanouts are simple with buffered I/O. Dirty blocks can be rolled back and kept in the buffer cache and can be accessed without having to undergo block cleanout.

One Response to “Understanding enhancements to block cleanouts in Exadata part 1”

  1. […] « Understanding enhancements to block cleanouts in Exadata part 1 […]

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

 
%d bloggers like this: