テーマ

遅延ブロッククリーンアウトって意外とホイホイ起こることがわかったので検証。
再現方法とか実際どういう動きをしてるかとか見れたら良いかなと。

遅延ブロッククリーンアウトについては↓参照。 www.shift-the-oracle.com

ものすごーく分かりにくいが

通常のブロッククリーンアウトの場合
1. DML実行
  - データファイルから更新ブロックを読み取り
  - バッファの更新ブロックのITLにトランザクション開始を記録＆データを更新
2. コミット実行
  - バッファの更新ブロックのITLにトランザクション終了を記録（ブロッククリーンアウト）
3. チェックポイント発生
  - バッファ中の更新ブロックをデータファイルに書き出し
    ⇒このときブロック中のデータは更新済み＆ITLもトランザクション終了の状態　
    　
遅延ブロッククリーンアウトの場合
1. DML実行
  - データファイルから更新ブロックを読み取り
  - バッファの更新ブロックのITLにトランザクション開始を記録＆データを更新
2. トランザクション中にバッファの領域が不足
  - バッファ中の更新ブロックをデータファイルに書き出し
    ⇒このときブロック中のデータは更新済み＆ITLはトランザクション中の状態
3. コミット実行
  - バッファに更新ブロックが存在しないので再読み取りしてまでITLは更新しない（ブロッククリーンアウトが遅延）
4. 更新ブロックを参照するSQL実行
  - ブロックを読み取るがITLを見るとトランザクションが完了していないのでUNDOセグメントのトランザクションテーブルを見に行
  - トランザクションが終了していればブロックのITLにトランザクション終了を記録する（遅延ブロッククリーンアウト）

ということだと理解した。
多分あってるんじゃないかな。

方針

トランザクション中の各所でブロックダンプを取ってITLの変化を確認してみる。

検証1（通常のブロッククリーンアウト）

SQL> create tablespace test datafile '/tmp/test.dbf' size 100M --まっさらの表領域作成;

Tablespace created.

SQL> create table test(col char(1000)) tablespace test --適当な表作成;

Table created.

SQL> insert into test select '0' from dual connect by level <= 50 --多分10ブロックくらい使う;

50 rows created.

SQL> commit --バッファに存在する（と思われる）うちにコミット;

Commit complete.

SQL> alter system flush buffer_cache --ダンプ取得用に書き出し;

System altered.

SQL> select extent_id ,file_id ,block_id ,blocks from dba_extents where segment_name = 'TEST';

 EXTENT_ID    FILE_ID   BLOCK_ID     BLOCKS
---------- ---------- ---------- ----------
         0          5        128          8
         1          5        136          8

SQL> alter system dump datafile 5 block min 128 block max 144 --TEST表のブロックをダンプ;

System altered.

大体内容はコメントとして書いたので各操作の詳しい説明は割愛。
思惑としては単純にDMLを実行して通常通りのブロッククリーンアウトが行われた場合にITLがどういう状態になっているか見たいだけ。
取得したブロックダンプからITLだけ抽出すると以下。

$ egrep "^ Itl|^0x0|^Block header" orcl_ora_15980.trc
Block header dump:  0x01400083
 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x000a.018.0000030f  0x00c08ee9.00d6.09  --U-    7  fsc 0x0000.0011c632
0x02   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000
Block header dump:  0x01400084
 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x000a.018.0000030f  0x00c08ee9.00d6.0b  --U-    7  fsc 0x0000.0011c632
0x02   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000
Block header dump:  0x01400085
 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x000a.018.0000030f  0x00c08ee9.00d6.0d  --U-    7  fsc 0x0000.0011c632
0x02   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000
Block header dump:  0x01400086
 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x000a.018.0000030f  0x00c08ee9.00d6.0f  --U-    7  fsc 0x0000.0011c632
0x02   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000
　：
（略）

「Itl」はデフォルト値「2」なので「0x01-2」の2スロットで今回は「0x01」の方が使われてるわけ。
「Uba」がUNDOセグメントに対するポインタ。
「Flag」と「Scn/Fsc」はトランザクション完了のフラグとタイミングを記録してるっぽい。
ちゃんとブロッククリーンアウトされている。

検証2（遅延ブロッククリーンアウト）

コミットする前に一回ブロックをフラッシュしてバッファが溢れた状況を再現する。

(新たに表領域＆テーブルを再作成する手順は略)

SQL> insert into test select '0' from dual connect by level <= 50;

50 rows created.

SQL> alter system flush buffer_cache --バッファを全て書き出してクリア;

System altered.

SQL> commit;

Commit complete.

SQL> select extent_id ,file_id ,block_id ,blocks from dba_extents where segment_name = 'TEST';

 EXTENT_ID    FILE_ID   BLOCK_ID     BLOCKS
---------- ---------- ---------- ----------
         0          5        128          8
         1          5        136          8

SQL> alter system dump datafile 5 block min 128 block max 144;

System altered.

これでITLにはまだトランザクションの終了が記録されないままデータだけが更新された状態でデータファイルに書き出されているはず。
取得したブロックダンプからITLを見てみると以下。

$ egrep "^ Itl|^0x0|^Block header" orcl_ora_15940.trc
Block header dump:  0x01400083
 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x0002.009.0000035b  0x00c00abe.00b3.0f  ----    7  fsc 0x0000.00000000
0x02   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000
Block header dump:  0x01400084
 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x0002.009.0000035b  0x00c00abe.00b3.11  ----    7  fsc 0x0000.00000000
0x02   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000
Block header dump:  0x01400085
 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x0002.009.0000035b  0x00c00abe.00b3.13  ----    7  fsc 0x0000.00000000
0x02   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000
Block header dump:  0x01400086
 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x0002.009.0000035b  0x00c00abe.00b3.15  ----    7  fsc 0x0000.00000000
0x02   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000
　：
（略）

「Flag」と「Scn/Fsc」が空のままなのでトランザクション中の状態と思われる。
この後SELECTを実行することで遅延ブロッククリーンアウトがされるはず。

SQL> alter system dump datafile 5 block min 128 block max 144;

System altered.

SQL> set autotrace traceonly
SQL> select count(*) from test;


Execution Plan
----------------------------------------------------------
Plan hash value: 1950795681

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

Note
-----
   - dynamic sampling used for this statement (level=2)


Statistics
----------------------------------------------------------
          5  recursive calls
          0  db block gets
         41  consistent gets
         14  physical reads
        620  redo size
        526  bytes sent via SQL*Net to client
        524  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          1  rows processed

SQL> alter system flush buffer_cache;

System altered.

SQL> alter system dump datafile 5 block min 128 block max 144;

System altered.

「redo size」が地味に620程発生している。
SELECTしているだけなので普通ならREDOが発生することはないはず。
この時点でなんらか更新がされていることが分かる。
なんとなく読み取りが多いのもUNDOセグメントを読みに言っているからじゃなかろうか。
もっと詳細に見たい場合はEVENT 10046トレースとかとってみると良いかもしれない。
取得したブロックダンプを見てみる。

Block header dump:  0x01400083
 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x0002.009.0000035b  0x00c00abe.00b3.0f  C---    0  scn 0x0000.0011c47f
0x02   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000
Block header dump:  0x01400084
 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x0002.009.0000035b  0x00c00abe.00b3.11  C---    0  scn 0x0000.0011c47f
0x02   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000
Block header dump:  0x01400085
 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x0002.009.0000035b  0x00c00abe.00b3.13  C---    0  scn 0x0000.0011c47f
0x02   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000
Block header dump:  0x01400086
 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x0002.009.0000035b  0x00c00abe.00b3.15  C---    0  scn 0x0000.0011c47f
0x02   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000
　：
（略）

SELECTしただけなのにITLが更新されている。
遅延ブロッククリーンアウトが発生したっぽい。やったぜ！
いまいち「Flag」列が「C」だったり「U」だったりする条件は良く分からない。

まとめ

遅延ブロッククリーンアウトの様子は確認できた。

ちなみにそもそもバッファキャッシュを経由しないダイレクトパスインサートの場合も同様にブロッククリーンアウトが遅延された状態になった。
しかもその後SELECTしてもブロッククリーンアウトされなかった。
きっと確実に大量の遅延ブロッククリーンアウトが発生してしまうダイレクトパスインサートの場合だけ気を利かせて余計な負荷が掛からないようにしてくれてるんだと思う。
これはこれで微妙に問題がありそう。

SQL*Plusの使いにくさは異常

主にOracleネタの検証ブログ。

遅延ブロッククリーンアウトを観測する①

テーマ

方針

検証1（通常のブロッククリーンアウト）

検証2（遅延ブロッククリーンアウト）

まとめ