kagamihogeの日記

kagamihogeの日記です。

statspack練習にコミット間隔有無で比較

DB Oracle Java プログラミング失敗談

statspackさわる - kagamihogeの日記でstatspackを自分の環境で手軽に試せるようになった。なので、練習がてら分かりやすくハッキリと差が出るレポートを取得して眺めてみる。

やることは、10万回insertを実行するJavaのプログラムを2種類用意する。1つは、1回ごとにcommitする。もう1つは、1回だけ最後にcommitする。この2つの間でstatspackのレポートにどんな差が出るかを確認する。

環境

テーブルとプログラム準備

データを入れていくテーブルを作る。

DROP TABLE hoge_table PURGE;
ALTER SYSTEM SWITCH LOGFILE;
CREATE TABLE hoge_table 
(
  ID INTEGER NOT NULL 
, VALUE VARCHAR2(10) NOT NULL 
, CONSTRAINT hoge_table_pk PRIMARY KEY 
  (
    ID 
  )
  ENABLE 
);

プログラムを実行する前に、下記のSQL実行とOracle再起動をする。ログスイッチは、スイッチの回数に変化が生じるかを見るためにしている。

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM SWITCH LOGFILE;

insertを1回ごとに1回commitするJavaのプログラムを用意する。

public static void main(String[] args) throws SQLException {
    long start = System.currentTimeMillis();

    final String insertStr = "INSERT INTO hoge_table(ID, VALUE) VALUES(?, dbms_random.string('X', 10))";
    try (Connection connection = DriverManager.getConnection(
        "jdbc:oracle:thin:@192.168.0.20:1521:XE", "kagamihoge", "a");
        PreparedStatement sql = connection.prepareStatement(insertStr);) {
        connection.setAutoCommit(false);
        
        for (int i=0; i<100_000; i++) {
            sql.setInt(1, i);
            sql.executeUpdate();
            connection.commit();
        }
    }
    
    long end = System.currentTimeMillis();
    System.out.println(end - start);
}

上のコードをちょっと変更して、1回だけ最後にcommitするプログラムを用意する。

        for (int i=0; i<100_000; i++) {
            sql.setInt(1, i);
            sql.executeUpdate();
        }
        connection.commit();

まず実行時間の比較。

種類 1 2
1回ごと 1152953 1135906
1回だけ 49110 48859

ここまでは10万件INSERTを1件ずつコミットと1回だけコミットしたときの速度比較してみた - kagamihogeの日記とやったこと同じ。JDBC経由で100万件取得・追加してみた - kagamihogeの日記のjava.sql.Statement#addBatch(String sql)でラウンドトリップ減らせば更に速くなる。また、単純なデータロードならダイレクトパスロードでSQL*Loaderを使えば良い。

statspackレポートの比較

Top 5 Timed Events

statspackレポートのレポートを見るときは、まずこのセクションから見るらしい。なお、特に断りが無ければ、先が1回ごと、後が1回だけ、のレポートとする。

Top 5 Timed Events                                                    Avg %Total
~~~~~~~~~~~~~~~~~~                                                   wait   Call
Event                                            Waits    Time (s)   (ms)   Time
----------------------------------------- ------------ ----------- ------ ------
log file sync                                  100,026       1,034     10   49.2
log file parallel write                        100,052       1,025     10   48.8
CPU time                                                        24           1.1
db file async I/O submit                           122           8     62     .4
control file parallel write                        424           7     16     .3
          -------------------------------------------------------------
Top 5 Timed Events                                                    Avg %Total
~~~~~~~~~~~~~~~~~~                                                   wait   Call
Event                                            Waits    Time (s)   (ms)   Time
----------------------------------------- ------------ ----------- ------ ------
CPU time                                                         6          47.0
log file parallel write                             54           3     54   24.3
db file async I/O submit                             5           2    379   15.9
control file parallel write                         39           1     21    7.0
db file sequential read                            373           0      0    1.5
          -------------------------------------------------------------

1回ごとが遅い理由は、ここでほぼ説明が出来る。まず、1回ごとのlog file syncとlog file parallel writeが突出しているが、1回だけの方は極々小さい値になっている。この2つのイベントで待たされているから遅い、ということが分かる。では、この2つの待機イベントとは何者なのか、ということになる。

log file parallel write
LGWRプロセスがカレントログファイルに書込んでいる時の待機です。

log file sync
コミットなどのトランザクション確定時のREDOログファイル書込み待ちです（「log file parallel write」はLGWRプロセスの待ちですが、これはサーバープロセスの待ちです）。これは必ず発生する待機イベントです。REDOの書込みは整合性のため同期で行います（必ず書込み終了まで待ちます）ので、この書込み時間は多かれ少なかれ必ず待ちとして発生する訳です。

津島博士のパフォーマンス講座　第19回「UNDOデータとREDOログについて」

要するに、コミットするとディスク書き込みが発生する*1し、その書き込みはREDOログ整合性確保のため書き込み終了まで待たなくてはならない。厳密に言うと不正確な書き方ではあるのだけど、このエントリ内ではこんだけの理解でひとまず充分。

1回ごとコミットの場合の動作は、insertプラスcommitをするとREDOログファイル書込みに入る。そして、書き込みが終わる前に次のinsertプラスcommitが来るので待機を余儀なくされる（と思う）。いくら一回のREODログサイズが小さい（inser*1+commit*1だけ）とはいえ、メモリ上のログバッファに追加するほうが余程早いわけで、そこで待機することになる。HDDのアクセスランプを見ていると、1回ごとは点灯しっ放しになる。しかし、1回だけのほうはほとんどランプは点灯しない。この差も待機イベントの数字で説明が付く。

REDOログファイルへの書き込みは、Oracleがトランザクションをログ法で実現している以上避けようが無い。というか有って当たり前なので、log file syncやlog file parallel writeの待機イベントがある程度出てくるのは自然なことである。

かといって、頻繁にディスク書き込みがあっては性能は上がらない。そのための対策の1つがログバッファとなる。メモリ上にREDOログを適当に溜め込んでいって、適当なタイミングでディスクにまとめて書き込むことでディスク書き込みによる待機を減らすことが目的となる。まず、LGWRがREDOログを書き込むタイミングについて。一時的にせよメモリに置くことは喪失の危険があるので、性能とのバランスを見て色んなタイミングで書き込むようになっている、と思われる。

LGWRは、以下のタイミングでREDOデータをREDOログファイルに書き込みます。
・トランザクションがコミットされたとき
・DBWnがREDOデータの書き込みを要求したとき（更新済みブロックのデータファイルへの書き込み時など）
・3秒ごとのタイムアウトが発生したとき
・REDOログバッファの容量が不足したとき
・未書き込みREDOデータがREDOログバッファ全体の3分の1に達したとき

プロとしてのOracleアーキテクチャ入門 Oracle現場主義 CHAPTER 04 REDOログファイルとREDOデータ - REDOログバッファとLGWR p.52

ここで重要なのは、（LGWRは）トランザクションがコミットされたときREDOログバッファをファイルに書き込む、という点。1回ごとにcommitしていると、ログバッファに貯まるまでもなく即効でディスクにチマチマと書き出されていく。少量かつ高頻度でディスク書き込みが発生している、とも言える。Javaプログラム上では1ループごとなので10万回（Waits）それが発生する。対して1回だけの場合、トランザクションがコミットされたときの書き込みは1回だけとなる。statspack上、1回ごとはWaitsが100,026になっている所に現れている。

ちなみに、log file syncやlog file parallel writeがtop 5に出てくるのは、ぐぐってると割と「あるある」な事例なようである。事例紹介として、いわゆるバッチ系のプログラムで頻繁にコミットをし過ぎてるとこうなる、といった感じで紹介されてることが多い。このエントリでは、なぜそうなるかをカンタンなJavaのコードを書いてstatspackのレポートを取ることで、理解が深められた。

Load Profile

レポート対象期間中の1秒当たり、トランザクション当たりの統計情報。自分が重要だと感じた部分以外は割愛。

Load Profile              Per Second    Per Transaction    Per Exec    Per Call
~~~~~~~~~~~~      ------------------  ----------------- ----------- -----------
       Redo size:           70,615.9              845.9
   Logical reads:              527.6                6.3
   Block changes:              508.8                6.1
      User calls:              167.0                2.0
        Executes:               88.2                1.1
    Transactions:               83.5
Load Profile              Per Second    Per Transaction    Per Exec    Per Call
~~~~~~~~~~~~      ------------------  ----------------- ----------- -----------
       Redo size:          620,607.8       26,375,832.0
   Logical reads:            3,774.8          160,429.5
   Block changes:            4,808.1          204,342.0
      User calls:            1,176.6           50,006.5
        Executes:            1,206.4           51,273.5

ここは絶対値にはアンマリ意味がなく、その環境下での相対評価をして意味が出てくる。ここでは1回ごと・1回だけで相対評価することになる。比較してみると、1回だけの方がより多くのREDOやら処理やらをこなせていることが分かる。それは何故かといえば、1回ごとは待機されまくって他の処理が出来なかったから、ということになる。

Statistic

自分が重要だと感じた部分以外は割愛。

Statistic                                       Time (s) % DB time
----------------------------------- -------------------- ---------
DB CPU                                              65.9       6.1
sql execute elapsed time                            28.1       2.6
DB time                                          1,085.6
background elapsed time                          1,056.3
background cpu time                                 23.4
Statistic                                       Time (s) % DB time
----------------------------------- -------------------- ---------
DB CPU                                              32.5      99.1
sql execute elapsed time                            20.4      62.3
DB time                                             32.8
background elapsed time                              6.4
background cpu time                                  0.5

1回ごとは、バックグラウンド実行時間（background elapsed time）が半端無く多い。これは恐らく、上述の通りLGWRの待機イベントだと考えられる。

上の方に書いたがコミット時に現れる待機イベントは大別して2つある。log file parallel writeはLGWRプロセスで、log file syncはサーバプロセスの待機である。これはちょっと想像になってしまうのだが、アプリケーションのプログラマから見るとバックグラウンドプロセスの待機は基本的には不可視である。直接的に見えるのはサーバプロセスの待機のみである。なので、裏側で何かが起きていたとしても気付くのは難しい*2　よって、このエントリの例の場合、Javaのコードだけを見ていると「なんか知らんがコミットが遅い」となるのではなかろうか。

他のサーバプロセスがある環境下で頻繁なコミットを繰り返せば、このエントリの例とは比較にならないほど待機が頻発してコミット処理は遅くなるハズである。自分自身でlog file syncを大量に引き起こすわ、他のプロセスのlog file parallel writeで待機させられるわ、で良いことが無い。この辺については後で改めて触れたい。

Event
                                                             Avg          %Total
                                          %Tim Total Wait   wait    Waits   Call
Event                               Waits  out   Time (s)   (ms)     /txn   Time
---------------------------- ------------ ---- ---------- ------ -------- ------
log file sync                     100,025    0      1,034     10      1.0   49.2
db file sequential read               708    0          2      3      0.0     .1
log file switch completion              2    0          0    112      0.0     .0
db file scattered read                  8    0          0      4      0.0     .0
resmgr:cpu quantum                      1    0          0      7      0.0     .0
control file sequential read          209    0          0      0      0.0     .0
Disk file operations I/O               10    0          0      0      0.0     .0
SQL*Net message from client       200,004    0      1,249      6      2.0
jobq slave wait                       601  100        301    501      0.0
SQL*Net message to client         200,004    0          1      0      2.0
          -------------------------------------------------------------
                                                             Avg          %Total
                                          %Tim Total Wait   wait    Waits   Call
Event                               Waits  out   Time (s)   (ms)     /txn   Time
---------------------------- ------------ ---- ---------- ------ -------- ------
db file sequential read               368    0          0      0    184.0    1.5
log buffer space                        1    0          0    175      0.5    1.5
log file switch completion              1    0          0    134      0.5    1.1
log file sync                           3    0          0     24      1.5     .6
db file scattered read                 19    0          0      2      9.5     .3
control file sequential read          173    0          0      0     86.5     .0
SQL*Net message from client       100,005    0        104      1 ########
SQL*Net message to client         100,005    0          0      0 ########
          -------------------------------------------------------------

このセクションで興味深いのはSQL*Net message from clientのところ。Wait Timeが1,249なのは実際にはlog file syncによるものなので良いとして、Waitsが20万になっている。この数値は、アプリからOracleに対して20万回SQLなどの命令要求があったことを示している。1回ごとでは、insert + commitの2 * 10万で20万と思われる。1回だけのほうは10万である。この例の場合は回数は大して問題になっていないと思われる。

しかし、JDBCのバッチ更新でこの部分の改善をすると更に高速化する。コード例は省略*3するが、バッチサイズを100にすると、この例の場合SQL*Net message from clientが1,000くらいになる。100 * 1000で10万。Oracleとの通信回数を減らすことで性能アップが見込める理由は、このあたりの数値となって現れる。

Statistic

このセクションは各統計情報の項目がどれだけあったかを示している。経過時間ごと、経過トランザクションごとなので、これも相対値で比較して意味が出てくる。ただ、このエントリの例の場合、1回ごとの方が経過時間がかなり長いので、その分だけ相対的に数字が大きくなる。

Statistic                                      Total     per Second    per Trans
--------------------------------- ------------------ -------------- ------------
CPU used by this session                       2,394            2.0          0.0
CPU used when call started                     2,317            1.9          0.0
IMU Redo allocation size                     366,804          306.2          3.7
IMU commits                                   99,084           82.7          1.0
IMU undo allocation size                 106,608,112       88,988.4      1,066.0
db block changes                             609,566          508.8          6.1
redo size                                 84,597,804       70,615.9        845.9
redo synch time (usec)                 1,035,021,368      863,957.7     10,349.6
session pga memory max                    21,709,712       18,121.6        217.1
session uga memory max                    25,763,832       21,505.7        257.6
Statistic                                      Total     per Second    per Trans
--------------------------------- ------------------ -------------- ------------
CPU used by this session                         560            6.6        280.0
CPU used when call started                       604            7.1        302.0
IMU Redo allocation size                      10,056          118.3      5,028.0
IMU commits                                        0            0.0          0.0
IMU undo allocation size                       5,152           60.6      2,576.0
db block changes                             408,684        4,808.1    204,342.0
redo size                                 52,751,664      620,607.8 ############
redo synch time (usec)                        71,869          845.5     35,934.5
session pga memory max                     9,044,016      106,400.2  4,522,008.0
session uga memory max                     8,897,248      104,673.5  4,448,624.0

ここで目を引くのはredo sizeの項目。1回ごとのTotalは約84M、1回だけは約52Mになっている。この差は、コミットしたという情報もREDOログに書き込まれるため、と考えられる。なのでREDOログには insert,commit,insert,commit...という構造になっているハズである。1回だけの場合は、insert,insert,insert,...,commitという構造になるので、サイズは減る。

というわけで、試しにコミットだけを繰り返すプログラムを実行してみる。

connection.setAutoCommit(false);
for (int i=0; i<100_000; i++) {
    connection.commit();
}

このプログラムを実行したあとstatspackのレポートを取るとredo sizeはガン増えする。なので、追加更新削除が何も無くても、コミットをするとただそれだけでOracleに負荷をかけることになる。*4ただ、先にも書いた通りコミットはOracleに無くてはならない処理である。なので、何がコミットすべき単位なのか・トランザクションはどこからどこまでなのか、を考える必要が出てくる。これは後で考えたい。

あと、CPU used by this sessionやsession pga|uga memory maxも1回だけのほうが少なくエコである。

Statistic - log switches
Statistic                                      Total  per Hour
--------------------------------- ------------------ ---------
log switches (derived)                             2      6.01
Statistic                                      Total  per Hour
--------------------------------- ------------------ ---------
log switches (derived)                             1     42.35

ログスイッチの回数は、1回ごとが2回だが、1回だけは1回で済んでいる。どちらのプログラムも結果として10万件レコードが追加されることには変わらないが、Oracleの内部的にはだいぶ異なる結果となっているのが伺える。なおJDBCのバッチ更新を利用すると0回となった。redo sizeが小さくなるのだから当然といえば当然なのだけど。

感想とかチラ裏

何がトランザクションなのか

Oracleにおけるコミットは、何も更新するものがなくても負荷のかかる処理、ということをレポートを示しながら書いた。また、トランザクションを実現するためにコミットは必要不可欠である。なので、適当な単位でコミットをすることが開発者には要求される。でまぁ、適当な単位とは一体何なんだ、ということになる。

ここから先は、まだ俺自身トランザクションの理解が浅いこともあり、感想あるいはチラ裏なのだけど。

まず、トランザクションを論理レベルの単位として表現しなければいけないものは何か、ということになる。論理レベルというのは、ビジネスとか業務とかの単位のこと。トランザクションの例で出てくる銀行口座のアレとかああいうの。ビジネス上でここからここまでが分解不可能な一単位だ、という代物が、論理レベルのトランザクションの一単位に相当する、と考えられる。でまぁ、オンラインだと注文とかバッチだと残高繰越だとか、基本的には境界がハッキリしているモンである。

論理レベルでのトランザクションは基本的にはハッキリしているのだけど、必ずしもハッキリするとは限らない。会計みたいにルールが決まってるのとか、お客さんの注文みたいに金が絡むから必然的に決まるのは良い。例えばこのエントリの例のようにデータ突っ込むだけのバッチとかは、論理レベル・ビジネス上の一単位は何なんだろうか？　と俺は疑問に思う。まぁこの場合、一件だろうが全件だろうが、データが揃ってさえいればボクは満足するんだ、というのが実際のところなんだろうけど。

ビジネス的というよりシステム的に実施しなければならない処理とか、その会社固有の業務処理で何が一単位なのかイマイチ不明な処理とかは、どこからどこまでをトランザクションと捉えるべきなのか。この辺はこれから勉強しないといかんなーと思う。

もちろん、物理レベルの制約も考慮しなければならない。いくらUNDOセグメントが自動拡張するからって、領域不足になるような大きすぎるトランザクションは実現不可能である。このエントリの例で言えば、1件ずつコミットするのは明らかにオーバーヘッド過剰で、最後に1回だけコミットすれば充分そうである。勿論、この程度の負荷どっちだって知ったことか、というのもアリだと思う。とはいえ、論理レベルの要求を実現するために、物理レベルでなるべく安く済む手段を取ることが、開発者の責務と言えそうな感じである。

が、この辺結構めんどくさいこと色々考えなければならないのだけど、プログラマにまとめて投げ捨てられてるのが現状である。

プログラマの不安

実を言うと、このエントリの1件ずつコミットは俺自身がやっちまったことのある失敗談である。最も、Oracle関連の本とか資料とか見てると、よくある失敗事例として見かけるので、俺に固有の失敗事例というわけでもない。それはともかく、何故そういうコードを書いてしまったか、ということについて考えたい。

まず、コミットが重い処理だと知らないことが挙げられる。コミットすればデータが確定される、ぐらいの知識なので、小まめにセーブしとけばおｋだろう、程度の判断。また、なるべく速くコミットしなければデータが保持されないのではないか、という不安もある。

このような知識不足やそれに起因する不安にかられて過剰にコミットを連発すると性能上不利な事象となって現れる。なお悪いことにコード上では本当に些細な違いでしかない。また、データ量が少なければ特に問題無く動いてしまうので、ずっと後になってから性能劣化が表面化する遠因にもなってしまう。なんつーかまぁ知らないってのは本当に恐ろしい。

俗に経験豊富なDBAがプロジェクト早期から参画すると失敗の確率が減ると言われるけど、こういうポイントを早期に潰していけるからなのだろう、と推測される。

参考URL

*1:これは不正確で、グループ・コミットがあるので必ずしもそうなるとは限らないが、このエントリでは他のセッションがいないのでほとんど関係が無い

*2:詳しい仕組みを知らなくても利益を享受出来るのがミドルウェアの利点でもあるのだが

*3:http://d.hatena.ne.jp/kagamihoge/20120628/1340884433

*4:Oracleにおいて空コミットはほとんど性能に影響しない http://kagamihoge.hatenablog.com/entry/2014/03/02/160514