SELECTなのに更新処理？！～遅延ブロッククリーンアウトの動きに迫る～

この記事は、JPOUG Advent Calendar 2024 16日目の記事です。
15日目は Shinjiro Fujita さんの記事「Oracle Database 23ai 新機能「リアルタイムSQL計画管理 (SPM)」を試してみた #oracle - Qiita」でした。
今回はOracle Databaseの遅延ブロッククリーンアウトについて調査、検証してみました。
なぜ遅延ブロッククリーンアウトが気になったのか忘れたのですが、半年ぐらい前にとあるWebサイトで遅延ブロッククリーンアウトについて書かれている記事を見つけ、その不思議な動きに興味を持ったのだと思います。
しかし、仕組みが（私にとっては）非常に複雑で初めて読んだときはまったく理解できませんでした。
私自身は過去の業務で遅延ブロッククリーンアウトに遭遇したことはないのですが、Oracle界隈では割と有名な話だそうで、自身のナレッジの1つとして調査、検証してみました。

ブロッククリーンアウトとは？
遅延ブロッククリーンアウトについて調べる前にそもそもブロッククリーンアウトとは何か調べてみました。
ブロッククリーンアウトは、データブロックのITL（データブロックを更新しているトランザクションのリスト）に登録されているトランザクションの状態をコミット済みとして記録します。
※ブロッククリーンアウトとチェックポイントは同時には発生しないため、この時点ではバッファとデータファイルで同期されていない可能性があります。
【補足】
ITL（Interested Transaction List）
「Interested」という単語自体知らなかったので辞書で調べてみました。直訳すると「興味があるトランザクションの一覧」になります。
「Oracleが管理するトランザクションの一覧」といったニュアンスでしょうか。
ITLはデータブロックヘッダーに存在し、データブロックを更新しているトランザクションをエントリとして管理します。
なお、OracleはITLエントリの情報から未コミット/コミット済みを判断します。

遅延ブロッククリーンアウトとは？
上記の内容を前提として、遅延ブロッククリーンアウトについて調べてみました。
遅延ブロッククリーンアウトは、未コミット状態となっているデータブロックのITLエントリ（トランザクションの状態）をコミット発行したタイミングではなく、別トランザクションが次回該当データブロックにアクセスしたときにコミット済みに更新（記録）します。
バッチなどで大量のデータを処理する際、未コミットやコミット済みのデータブロックが溜まり続けることでバッファ・キャッシュ領域が枯渇する場合があります。
その場合、Oracleはバッファ・キャッシュ領域に空きを確保するため、トランザクションが未コミット/コミット済みに関わらずデータファイルに書き込みます。
コミット発行された場合、ITLエントリ（トランザクションの状態）をコミット済みに更新する必要がありますが、退避したデータブロックを再度バッファ・キャッシュ領域にロードせず、UNDOセグメントヘッダーのトランザクション表（TRN TBL）にコミット済みであることを記録しておきます。
しかし、この時点ではデータファイルのデータブロックのITLエントリは未コミット状態のままです。
ではデータファイルのデータブロックのITLエントリは誰がいつコミット済みに更新するのでしょうか？
それは次回該当データブロックにアクセスしたトランザクション（SELECT含む）です。
次回該当データブロックにアクセスしたトランザクションがトランザクション表を参照し、コミット発行済みであると判断し、データブロックのITLエントリをコミット済みに更新します。
更新処理（ITLの書き換え）が発生するため、たとえSELECTでもREDOデータが発生します。
なお、トランザクション表を参照する際、シングルブロックリードとなります。（Oracleの仕様）

こんがらがってきたので下記のように整理してみました。
・遅延ブロッククリーンアウトはバッファ・キャッシュ領域の枯渇により発生する
・コミット発行後、ITLエントリ更新のために退避したデータブロックを再度バッファ・キャッシュ領域にはロードしない（コミット済みであることをUNDOセグメントヘッダーに記録しておく）
・次回該当データブロックにアクセスしたトランザクションがITLエントリをコミット済みに更新する（REDOデータが発生する）
・トランザクション表へのアクセスはシングルブロックリードとなる（Oracle ExadataのSmart Scanも効かないという弊害がある）

文章や図だけだといまいちピンと来ないので、実際に検証してみました。
※図の例はUPDATEですが、検証はINSERTで実施しています。

検証環境
OS：Oracle Linux 7.9
DB：Oracle Database 19c Release Update 3 (19.3.0.0.0) Enterprise Edition

前提
・バッファ・キャッシュサイズは約1.5GB
・事前に検証用表領域、検証用テーブルは作成済み（表領域名：APP_TS、テーブル名：APL_TBL）

検証シナリオ
●パターン１（通常のブロッククリーンアウト）
手順１．トランザクション実行
手順２．コミット発行
手順３．バッファ・キャッシュのフラッシュ
手順４．ブロック・ダンプ取得
手順５．別セッションにて該当データブロックにアクセス（SELECT）

●パターン２（遅延ブロッククリーンアウト）
手順１．トランザクション実行
手順２．バッファ・キャッシュのフラッシュ
手順３．コミット発行
手順４．ブロック・ダンプ取得（遅延ブロッククリーンアウト発生前）
手順５．別セッションにて該当データブロックにアクセス
手順６．ブロック・ダンプ取得（遅延ブロッククリーンアウト発生後）
手順７．別セッションにて該当データブロックにアクセス（遅延ブロッククリーンアウトの解消確認）

検証ログ
●パターン１（通常のブロッククリーンアウト）
手順１．トランザクション実行
トランザクション（今回は検証用テーブルにデータINSERT(1000件)）を開始します。
後述のITLエントリのトランザクションとの突合用にトランザクション情報も取得しておきます。

[oracle@vm-oel7 ~]$ sqlplus / as sysdba
SQL> INSERT INTO APP_TBL SELECT LPAD(LEVEL, 1000, '0') FROM DUAL CONNECT BY LEVEL <= 1000;

1000 rows created.

SQL> --アクティブ・トランザクション確認
SQL> select
2 xid,
3 xidusn,
4 xidslot,
5 xidsqn,
6 ubablk,
7 ubasqn,
8 ubarec,
9 status,
10 start_ubablk,
11 start_ubasqn,
12 start_ubarec,
13 used_ublk,
14 used_urec,
15 start_scn
16 from
17 v$transaction
18 order by
19 xid;

XID XIDUSN XIDSLOT XIDSQN UBABLK UBASQN UBAREC STATUS START_UBABLK START_UBASQN START_UBAREC USED_UBLK USED_UREC START_SCN
---------------- ---------- ---------- ---------- ---------- ---------- ---------- --------------- ------------ ------------ ------------ ---------- ---------- ----------
0A0010009E040000 10 16 1182 1839 276 55 ACTIVE 1835 276 28 4 250 2711411

手順２．コミット発行
コミットを実行し、トランザクションを終了します。

SQL> commit;

Commit complete.

手順３．バッファ・キャッシュのフラッシュ
バッファ・キャッシュをフラッシュし、疑似的にコミット発行後にバッファ・キャッシュが枯渇した状態にします。
※未コミット/コミット済みに関わらずデータブロックはデータファイルに書き込まれます。

SQL> alter system flush buffer_cache;

System altered.

手順４．ブロック・ダンプ取得
コミット発行後にバッファ・キャッシュをフラッシュした状態のデータブロックのITLを確認するため、検証用テーブルのデータブロックの情報をダンプします。
※検証ログのダンプ結果はトランザクションが存在するエントリのみ表示しています。

SQL> --検証テーブルが使っているブロック特定
SQL> select
2 segment_name
3 , file_id
4 , extent_id
5 , block_id
6 , blocks --extent size(uniform) / block size
7 , round(bytes / 1024 / 1024, 2) as used_mb
8 from
9 dba_extents
10 where
11 segment_name = 'APP_TBL'
12 order by
13 extent_id,
14 block_id;

SEGMENT_NAME FILE_ID EXTENT_ID BLOCK_ID BLOCKS USED_MB
------------------------- ---------- ---------- ---------- ---------- -------------------
APP_TBL 5 0 8696 8 0.06
（中略）
APP_TBL 5 19 8848 8 0.06

SQL> --ブロック・ダンプ取得
SQL> alter session set tracefile_identifier = 'pt1';

Session altered.

SQL> alter system dump datafile 5 block min 8696 block max 8855;

System altered.

最初のブロックのエントリ番号 0x01 の Xid（0x000a.010.0000049e）のピリオドで区切られた値をそれぞれ10進表記にすると、アクティブ・トランザクションのXIDUSN、XIDSLOT、XIDSQNの値と一致していることが分かります。
Uba もピリオドで区切られた値をそれぞれ10進表記にすると、アクティブ・トランザクションの値と一致していることが分かります。
・0x0100072b は 0x01 を除いた値（00072b）はSTART_UBABLK
・0114 はSTART_UBASQN
・1c はSTART_UBAREC
と一致していることが分かります。
なお、最後のブロックのエントリ番号 0x01 の
・0x0100072b は 0x01 を除いた値（00072f）はUBABLK
・0114 はUBASQN
・37 はUBAREC
とXidは固定なのに対し、Ubaはブロック番号とレコード番号が可変になっています。
おそらくUNDOセグメントは循環利用なので可変になっているのではと思います。
上記からアクティブ・トランザクションはトランザクション開始時のUNDOデータとカレントのUNDOデータの両方を持っていることが分かりました。
（UNDOブロックもダンプしてみようと思ったのですが、そこまで検証時間を確保できませんでした…）
また、各エントリの Flag は --U-（コミット済み）になっていることも確認できました。
Scn にも値が入っており、エントリのトランザクションは終了していることも確認できました。

手順５．別セッションにて該当データブロックにアクセス
コミット発行後にバッファ・キャッシュをフラッシュした状態のデータブロックにアクセス（今回はSELECT）します。
アクセスしたときの実行統計や待機イベントも確認してみます。

[oracle@vm-oel7 ~]$ sqlplus / as sysdba
SQL> set autotrace on
SQL> select count(*) from app_tbl;

COUNT(*)
----------
1000

Execution Plan
----------------------------------------------------------
Plan hash value: 1770987

----------------------------------------------------------------------
| Id | Operation | Name | Rows | Cost (%CPU)| Time |
----------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 42 (0)| 00:00:01 |
| 1 | SORT AGGREGATE | | 1 | | |
| 2 | TABLE ACCESS FULL| APP_TBL | 1200 | 42 (0)| 00:00:01 |
----------------------------------------------------------------------

Note
-----
- dynamic statistics used: dynamic sampling (level=2)

Statistics
----------------------------------------------------------
6 recursive calls
0 db block gets
236 consistent gets
152 physical reads
0 redo size
550 bytes sent via SQL*Net to client
390 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed

SQL> select
2 wait_class,
3 event,
4 total_waits,
5 total_waits_fg
6 from
7 v$system_event
8 order by
9 wait_class,
10 total_waits desc;

WAIT_CLASS EVENT TOTAL_WAITS TOTAL_WAITS_FG
-------------------- ---------------------------------------- ----------- --------------
Administrative index (re)build lock or pin object 102 102
Administrative OFS operation completion 1 1
Commit log file sync 6 5
（中略）
User I/O db file sequential read 4610 2803
User I/O db file scattered read 292 118
User I/O Disk file operations I/O 236 70

単なるSELECTなのでREDOデータは発生していませんでした。
遅延ブロッククリーンアウトは発生していない想定のため、「db file sequential read」は他起因によるものと思います。

●パターン２（遅延ブロッククリーンアウト）
手順１．トランザクション発行
トランザクション（今回は検証用テーブルにデータINSERT(1000件)）を開始します。
後述のITLエントリのトランザクションとの突合用にトランザクション情報も取得しておきます。
※パターン２検証前に状態をクリアするため、検証用テーブル再作成＆DB再起動しています。

[oracle@vm-oel7 ~]$ sqlplus / as sysdba
SQL> INSERT INTO APP_TBL SELECT LPAD(LEVEL, 1000, '0') FROM DUAL CONNECT BY LEVEL <= 1000;

1000 rows created.

XID XIDUSN XIDSLOT XIDSQN UBABLK UBASQN UBAREC STATUS START_UBABLK START_UBASQN START_UBAREC USED_UBLK USED_UREC START_SCN
---------------- ---------- ---------- ---------- ---------- ---------- ---------- ---------------- ------------ ------------ ------------ ---------- ---------- ----------
04001B0012050000 4 27 1298 89968 337 58 ACTIVE 89956 337 31 4 250 2719034

手順２．バッファ・キャッシュのフラッシュ
バッファ・キャッシュをフラッシュし、疑似的にコミット発行前にバッファ・キャッシュが枯渇した状態にします。
※未コミット/コミット済みに関わらずデータブロックはデータファイルに書き込まれます。

SQL> alter system flush buffer_cache;

System altered.

手順３．コミット発行
コミットを実行し、トランザクションを終了します。

SQL> commit;

Commit complete.

手順４．ブロック・ダンプ取得（遅延ブロッククリーンアウト発生前）
コミット発行前にバッファ・キャッシュをフラッシュした状態のデータブロックのITLを確認するため、検証用テーブルのデータブロックの情報をダンプします。
※検証ログのダンプ結果はトランザクションが存在するエントリのみ表示しています。

SQL> --ブロック・ダンプ取得
SQL> alter session set tracefile_identifier = 'pt2_before_delayed_block_cleanout';

Session altered.

SQL> alter system dump datafile 5 block min 8696 block max 8855;

System altered.

[oracle@vm-oel7 ~]$ ls -ltr /u01/app/oracle/diag/rdbms/orcl19c/orcl19c/trace/orcl19c_ora_*.trc
-rw-r----- 1 oracle oinstall 3663965 11月 14 10:26 /u01/app/oracle/diag/rdbms/orcl19c/orcl19c/trace/orcl19c_ora_11954_pt1.trc
-rw-r----- 1 oracle oinstall 10690 11月 14 10:28 /u01/app/oracle/diag/rdbms/orcl19c/orcl19c/trace/orcl19c_ora_12167.trc
-rw-r----- 1 oracle oinstall 20035 11月 14 10:28 /u01/app/oracle/diag/rdbms/orcl19c/orcl19c/trace/orcl19c_ora_12204.trc
-rw-r----- 1 oracle oinstall 1214 11月 14 10:28 /u01/app/oracle/diag/rdbms/orcl19c/orcl19c/trace/orcl19c_ora_12292.trc
-rw-r----- 1 oracle oinstall 1182 11月 14 10:28 /u01/app/oracle/diag/rdbms/orcl19c/orcl19c/trace/orcl19c_ora_12302.trc
-rw-r----- 1 oracle oinstall 3657511 11月 14 10:35 /u01/app/oracle/diag/rdbms/orcl19c/orcl19c/trace/orcl19c_ora_12754_pt2_before_delayed_block_cleanout.trc
[oracle@vm-oel7 ~]$ egrep "^ Itl|^0x0|^Block header dump" /u01/app/oracle/diag/rdbms/orcl19c/orcl19c/trace/orcl19c_ora_12754_pt2_before_delayed_block_cleanout.trc
Block header dump: 0x000021fb
Itl Xid Uba Flag Lck Scn/Fsc
0x01 0x0004.01b.00000512 0x01015f64.0151.23 ---- 7 fsc 0x0000.00000000
0x02 0x0000.000.00000000 0x00000000.0000.00 ---- 0 fsc 0x0000.00000000
Block header dump: 0x000021fc
Itl Xid Uba Flag Lck Scn/Fsc
0x01 0x0004.01b.00000512 0x01015f64.0151.25 ---- 7 fsc 0x0000.00000000
0x02 0x0000.000.00000000 0x00000000.0000.00 ---- 0 fsc 0x0000.00000000
（中略）
Block header dump: 0x0000228f
Itl Xid Uba Flag Lck Scn/Fsc
0x01 0x0004.01b.00000512 0x01015f70.0151.2e ---- 7 fsc 0x0000.00000000
0x02 0x0000.000.00000000 0x00000000.0000.00 ---- 0 fsc 0x0000.00000000
Block header dump: 0x00002296
Itl Xid Uba Flag Lck Scn/Fsc
0x01 0x0004.01b.00000512 0x01015f70.0151.3a ---- 6 fsc 0x0000.00000000
0x02 0x0000.000.00000000 0x00000000.0000.00 ---- 0 fsc 0x0000.00000000

XidやUbaの見方はパターン１で説明してみたので割愛します。
コミット発行したにも関わらず、エントリの Flag は ----（未コミット）になっていました。
また、Scn も値が入っておらず、トランザクションは終了していない状態になっていました。

[oracle@vm-oel7 ~]$ sqlplus / as sysdba
SQL> set autotrace on
SQL> select count(*) from app_tbl;

COUNT(*)
----------
1000

Execution Plan
----------------------------------------------------------
Plan hash value: 1770987

Note
-----
- dynamic statistics used: dynamic sampling (level=2)

Statistics
----------------------------------------------------------
6 recursive calls
0 db block gets
379 consistent gets
152 physical reads
12628 redo size
550 bytes sent via SQL*Net to client
390 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed

SQL> select
2 wait_class,
3 event,
4 total_waits,
5 total_waits_fg
6 from
7 v$system_event
8 order by
9 wait_class,
10 total_waits desc;

WAIT_CLASS EVENT TOTAL_WAITS TOTAL_WAITS_FG
-------------------- ---------------------------------------- ----------- --------------
Administrative index (re)build lock or pin object 102 102
Administrative OFS operation completion 1 1
Commit log file sync 5 5
（中略）
User I/O db file sequential read 11591 7756
User I/O db file scattered read 301 117
User I/O Disk file operations I/O 249 71

単なるSELECTなのにREDOデータが生成されていることが確認できました。
また、フルスキャンなのにパターン１に比べ、「db file sequential read」が増えていることも確認できました。（UNDOセグメントにアクセスしている想定）
（AWRやASHレポートも見てみようと思ったのですが、そこまで検証時間を確保できませんでした…）

手順６．ブロック・ダンプ取得（遅延ブロッククリーンアウト発生後）
遅延ブロッククリーンアウト発生後のデータブロックのITLを確認するため、検証用テーブルを構成するブロックの情報をダンプします。
※検証ログのダンプ結果はトランザクションが存在するエントリのみ表示しています。

SQL> --ブロック・ダンプ取得
SQL> alter session set tracefile_identifier = 'pt2_after_delayed_block_cleanout';

Session altered.

SQL> alter system dump datafile 5 block min 8696 block max 8855;

System altered.

SQL> exit
[oracle@vm-oel7 ~]$ ls -ltr /u01/app/oracle/diag/rdbms/orcl19c/orcl19c/trace/orcl19c_ora_*.trc
-rw-r----- 1 oracle oinstall 3663965 11月 14 10:26 /u01/app/oracle/diag/rdbms/orcl19c/orcl19c/trace/orcl19c_ora_11954_pt1.trc
-rw-r----- 1 oracle oinstall 10690 11月 14 10:28 /u01/app/oracle/diag/rdbms/orcl19c/orcl19c/trace/orcl19c_ora_12167.trc
-rw-r----- 1 oracle oinstall 20035 11月 14 10:28 /u01/app/oracle/diag/rdbms/orcl19c/orcl19c/trace/orcl19c_ora_12204.trc
-rw-r----- 1 oracle oinstall 1214 11月 14 10:28 /u01/app/oracle/diag/rdbms/orcl19c/orcl19c/trace/orcl19c_ora_12292.trc
-rw-r----- 1 oracle oinstall 1182 11月 14 10:28 /u01/app/oracle/diag/rdbms/orcl19c/orcl19c/trace/orcl19c_ora_12302.trc
-rw-r----- 1 oracle oinstall 3657511 11月 14 10:35 /u01/app/oracle/diag/rdbms/orcl19c/orcl19c/trace/orcl19c_ora_12754_pt2_before_delayed_block_cleanout.trc
-rw-r----- 1 oracle oinstall 7416343 11月 14 10:38 /u01/app/oracle/diag/rdbms/orcl19c/orcl19c/trace/orcl19c_ora_13005_pt2_after_delayed_block_cleanout.trc
[oracle@vm-oel7 ~]$ egrep "^ Itl|^0x0|^Block header dump" /u01/app/oracle/diag/rdbms/orcl19c/orcl19c/trace/orcl19c_ora_13005_pt2_after_delayed_block_cleanout.trc
Block header dump: 0x000021fb
Itl Xid Uba Flag Lck Scn/Fsc
0x01 0x0004.01b.00000512 0x01015f64.0151.23 C--- 0 scn 0x0000000000297d7a
0x02 0x0000.000.00000000 0x00000000.0000.00 ---- 0 fsc 0x0000.00000000
Block header dump: 0x000021fc
Itl Xid Uba Flag Lck Scn/Fsc
0x01 0x0004.01b.00000512 0x01015f64.0151.25 C--- 0 scn 0x0000000000297d7a
0x02 0x0000.000.00000000 0x00000000.0000.00 ---- 0 fsc 0x0000.00000000
（中略）
Block header dump: 0x0000228f
Itl Xid Uba Flag Lck Scn/Fsc
0x01 0x0004.01b.00000512 0x01015f70.0151.2e C--- 0 scn 0x0000000000297d7a
0x02 0x0000.000.00000000 0x00000000.0000.00 ---- 0 fsc 0x0000.00000000
Block header dump: 0x00002296
Itl Xid Uba Flag Lck Scn/Fsc
0x01 0x0004.01b.00000512 0x01015f70.0151.3a C--- 0 scn 0x0000000000297d7a
0x02 0x0000.000.00000000 0x00000000.0000.00 ---- 0 fsc 0x0000.00000000

遅延ブロッククリーンアウトが発生したため、エントリの Flag は C---（コミット済み）になっていました。
また、Scn も値が入っており、トランザクションが終了した状態になっていました。

手順７．別セッションにて該当データブロックにアクセス（遅延ブロッククリーンアウトの解消確認）
遅延ブロッククリーンアウト発生後のデータブロックにアクセス（今回はSELECT）し、遅延ブロッククリーンアウトが解消されていることを確認します。
アクセスしたときの実行統計や待機イベントも確認してみます。

[oracle@vm-oel7 ~]$ sqlplus / as sysdba
SQL> set autotrace on
SQL> select count(*) from app_tbl;

COUNT(*)
----------
1000

Execution Plan
----------------------------------------------------------
Plan hash value: 1770987

Note
-----
- dynamic statistics used: dynamic sampling (level=2)

Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
154 consistent gets
0 physical reads
0 redo size
550 bytes sent via SQL*Net to client
390 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed

SQL> select
2 wait_class,
3 event,
4 total_waits,
5 total_waits_fg
6 from
7 v$system_event
8 order by
9 wait_class,
10 total_waits desc;

WAIT_CLASS EVENT TOTAL_WAITS TOTAL_WAITS_FG
-------------------- ---------------------------------------- ----------- --------------
Administrative index (re)build lock or pin object 102 102
Administrative OFS operation completion 1 1
Commit log file sync 6 6
（中略）
User I/O db file sequential read 11911 7917
User I/O db file scattered read 301 117
User I/O Disk file operations I/O 283 96

遅延ブロッククリーンアウトが解消されたため、REDOデータは生成されていないことが確認できました。
「db file sequential read」が多少増えていますが、今回は遅延ブロッククリーンアウトは発生していない想定のため、他起因によるものと思います。

対応案
遅延ブロッククリーンアウトの原因は「バッファ・キャッシュ領域の枯渇」ということを前提に対応案を考えてみました。