OracleのPL/SQLを使い無限ループでINSERTをし続けると何が起きるのか、をやる。実際には適当なところでキャンセルをかけたが、その理由も含めて表領域の状態やstatspackレポートの中身を見て何が起きるのかを確認していく。
環境
準備
1列だけのテーブルを作り、ここへINSERTし続ける。
DROP TABLE INFINITE_ROWS PURGE; CREATE TABLE INFINITE_ROWS ( C_VALUE VARCHAR2(20) );
無限ループでINSERTし続けるPL/SQLはこんな感じ。
create or replace PROCEDURE INSERT_INFINITE_ROWS AS BEGIN WHILE (1=1) LOOP INSERT INTO INFINITE_ROWS(C_VALUE) VALUES (dbms_random.string('X', 20)); END LOOP; END INSERT_INFINITE_ROWS;
上記のPL/SQLを実行する前に、バッファキャッシュのクリア・手動でログスイッチをしておく。
ALTER SYSTEM FLUSH BUFFER_CACHE; ALTER SYSTEM SWITCH LOGFILE;
やったこと・わかったこと
上記のPL/SQL実行後おおむね30分ほど経過したところで、SQL Developer上からPL/SQLのキャンセルボタンを押した。SQL Develperのログには下記のようなメッセージが表示された。
データベース192.168.0.20に接続中です。
IOエラー: No buffer space available (maximum connections reached?): recv failed
プロセスが終了しました。
データベース192.168.0.20から切断中です。
なお、キャンセル後すぐメッセージが戻ってきたわけではなく、体感では5,6分くらいはかかった。statspackを見る感じでは、30分PL/SQL実行でロールバックに5,6分といった感触である。この例では、本処理に対しロールバックに必要な所用時間はおおむね6/1らしいことが分かる。
次に、SQL Developerの「データベースの管理」機能で簡易的に表領域の状態を確認してみる。下のキャプチャは、上段が実行前、下段が実行後のもの。UNDO表領域（UNDOTBS1）が大きく、永続表領域（USERS）はソレナリに使用されていることが分かる。
OracleDBA〜UNDO管理〜 - メモ帳@wiki - Seesaa Wiki（ウィキ）を読む限り、INSERT時にUNDO表領域に書き込まれるのは新規ROWIDとなる。これが延々と溜まり続けるので、もしこの無限ループをし続けると、いずれUNDO表領域が不足するのでは、と考えられる。Oracle XEエディションでは、表領域は16GBの制限があるので自動UNDO管理がUNDO表領域をそこまで拡張した段階でエラーになる、とも考えられる。
ここで生じた疑問として、永続表領域が使用されているのが気になる。ロールバックされたのだからデータは削除されているのではないのだろうか？ まずは該当テーブルの使用ブロック数を確認する。
SELECT segment_name, bytes, blocks, extents FROM user_segments WHERE segment_name = 'INFINITE_ROWS';
| SEGMENT_NAME | BYTES | BLOCKS | EXTENTS |
|---|---|---|---|
| INFINITE_ROWS | 310378496 | 37888 | 108 |
確かにソレナリの量のブロックが確保されている。ではSELECTを発行したらどうなるだろうか。自動トレースも取ってみる。
SET AUTOTRACE ON SELECT * FROM INFINITE_ROWS;
統計
----------------------------------------------------------
11 recursive calls
2 db block gets
37460 consistent gets
37421 physical reads
228 redo size
276 bytes sent via SQL*Net to client
353 bytes received via SQL*Net from client
1 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
0 rows processed結果はゼロ件にも関わらず、実行時間はソレナリにかかっている。約30000ブロック読んでいるのだから時間がかかるのは当然である。これから分かるのは、HWMは上がりっぱなしになっている、ということ。UNDO表領域を使用してロールバックするとデータは削除されるものの、確保したブロックはそのまま、ということのようだ。
次はstatspackのレポートをチェックする。
Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time
----------------------------------------- ------------ ----------- ------ ------
CPU time 1,608 48.6
db file async I/O submit 1,363 776 569 23.4
db file sequential read 125,013 468 4 14.1
log file parallel write 4,420 299 68 9.0
control file parallel write 2,267 48 21 1.5
-------------------------------------------------------------db file async I/O submitはStrange “db file async I/O submit” wait event | Latch, mutex and beyondを読む限り俺の環境ではdb file parallel writeと考えて良いらしい。で、db file parallel writeは日本エクセム∥EXEM LABO∥Oracle Knowledge db file parallel writeを読むと「DBWRがバッファキャッシュの不良ブロックを整理するためにI/O要求を行います。その要求の 待機中に発生するものが、db file parallel writeイベントとなります。」とある。永続表領域が使用されている原因となる処理が確かに発生していることが伺える。
ログスイッチの回数はどのくらいだろうか。
Statistic Total per Hour --------------------------------- ------------------ --------- log switches (derived) 95 158.26
95回行われている。普通に考えると、二回ログスイッチが起きるとそれまでのREDOログは上書きされ始めるため、そこまでの変更済みデータはどこかに書き込まなければ障害発生時に失われてしまう……その時点では未コミットだったとしても。なのでチェックポイント時にDBWnがバッファキャッシュを永続表領域に書き込む。
topで見てるとメモリは一定以上消費されず、スワップも使われない。なので、少なくともバッファキャッシュから適当なタイミングで永続表領域に追い出されているのは確かである。
そしてロールバックの段階では、UNDO表領域のROWIDを元に永続表領域を順次削除していく。これでユーザからは、というか論理レベルでは、何も追加されてないテーブルが見えることになる。ただし、物理レベルではHWMが上がりっぱなしだが、これはまぁ運用でshrinkなりtruncateしてね、ってことな気がする。
