読者です 読者をやめる 読者になる 読者になる

kagamihogeの日記

kagamihogeの日記です。

コミットせずINSERTし続ける

Oracle DB

OraclePL/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)はソレナリに使用されていることが分かる。
f:id:kagamihoge:20140112163452p:plain

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してね、ってことな気がする。