kagamihogeの日記

kagamihogeの日記です。

JDBCのaddBatchとexecuteBatchの頻度変更時の動きをstatspackで見てみる

Java Oracle DB

JDBCのsetFetchSize変更時の動きをstatspackで見てみる - kagamihogeのblogに引き続いてstatspackの学習を続ける。昔書いたJDBC経由で100万件取得・追加してみた - kagamihogeのblogでは、JDBCのjava.sql.Statement#addBatch(String sql)とjava.sql.PreparedStatement#addBatch()呼び出しの頻度を変更するとDML文の実行速度が改善できる可能性があることを調べた。ここでは、なぜ速度が改善されるかを考える。やることとしては、バッチ更新を使用しないものと使用するものとで、それぞれstatspackのレポートを取得し、それらにどのような差が出るかを見てみる。

環境

準備

下記のようなテーブルを作り、ここへ100万件作成していく。また、バッチ更新有りと無しのそれぞれのプログラムを実行するとき、バッファキャッシュをクリアしておく。

DROP TABLE INSERT_TO_MILLION_ROWS_TABLE PURGE;
CREATE TABLE INSERT_TO_MILLION_ROWS_TABLE 
(
  COLUMN1 VARCHAR2(20) 
);

ALTER SYSTEM FLUSH BUFFER_CACHE;

計測対象のプログラム

バッチ更新を使用しない
package oraclestudy.fetchsize;

import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.PreparedStatement;

import org.apache.commons.lang3.RandomStringUtils;

public class InsertLoop {

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

        final String insertStr = "INSERT INTO insert_to_million_rows_table VALUES (?)";
        try (Connection connection = DriverManager.getConnection(
            "jdbc:oracle:thin:@192.168.0.20:1521:XE", "kagamihoge", "xxxx");
            PreparedStatement sql = connection.prepareStatement(insertStr);) {
            connection.setAutoCommit(false);
            
            for (int i=0; i<1_000_000; i++) {
                sql.setString(1, RandomStringUtils.randomAlphanumeric(20));
                sql.executeUpdate();
            }
            
            connection.commit();
        }

        long end = System.currentTimeMillis();
        System.out.println(end - start);
    }

}
バッチ更新を使用する

executeBatchを呼び出す頻度は100で固定。

package oraclestudy.fetchsize;

import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.PreparedStatement;

import org.apache.commons.lang3.RandomStringUtils;

public class InsertWithBatchUpdate {

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

        final String insertStr = "INSERT INTO insert_to_million_rows_table VALUES (?)";
        try (Connection connection = DriverManager.getConnection(
            "jdbc:oracle:thin:@192.168.0.20:1521:XE", "kagamihoge", "xxxx");
            PreparedStatement sql = connection.prepareStatement(insertStr);) {
            connection.setAutoCommit(false);
            
            for (int i=1; i<=1_000_000; i++) {
                sql.setString(1, RandomStringUtils.randomAlphanumeric(20));
                sql.addBatch();
                if (i % 100 == 0) {
                    sql.executeBatch();
                }
            }
            
            connection.commit();
        }

        long end = System.currentTimeMillis();
        System.out.println(end - start);
    }

}

実行時間

頻度／時間 1 2 3
なし 336063 339531 350203
100 14026 13860 13515

前書いたJDBC経由で100万件取得・追加してみた - kagamihogeのblogと比べると実行時間がかなり遅くなっているが、以前はOracleがlocalhostにあったのが、現在はネットワーク越しの別マシンに移動しているため。

速度はおおよそ23倍。

感想とか

下記の表は、statspackレポートから比較的差が見られるものを中心にピックアップした。

Statistic なし 100
SQL*Net roundtrips to/from client 1,000,017 10,017
bytes sent via SQL*Net to client 73,081,289 737,084
bytes received via SQL*Net from c 75,004,84 22,534,848

比較的わかりやすい差が出るのは、ラウンドトリップである。JDBCのバッチ更新を使用することで、Oracleとの通信回数を1/100にしている。そのため、ラウンドトリップも1/100になっている。次に、bytes sent via SQL*Net to clientだが、これもほぼ1/100になっている。Oracleから何を送り返しているといえば、JDBCのexecuteUpdateの返り値である、DMLが成功した行数が主なものと考えられる。よって、100万回逐次送り返していたものが、100個分で1回になれば、バイト数もそのような動きになるのは納得がいく。

対してbytes received via SQL*Net from clientのクライアントからOracleに送ったバイト数だが、こちらはキレイに100倍とはなってない。これを考えてみたい。まず、バッチ更新無しのケースで一回にどのくらいのバイト数が送信されているか。合計バイト数 / ループ回数、であるところの75,004,84 / 1,000,000 = 約75バイト。INSERT 〜のSQL文が50バイト、パラメータに20バイトの文字列で70バイト。パケット構成マッタク知らんのでウソ書いてる可能性高いけど、感覚としては合ってるよーな気がする*1。

同じ計算で行くと、22,534,848 / (1,000,000 / 100) が約2,253。ここに100回分のINSERTが詰まってるとして。内訳は、文字列20バイト×100=2,000にプラス、SQL文本体のデータサイズはPreparedStatementだから一回分で済むハズで、これが50とすると2050で、おおよそ約2,253に近くなる。パケットの中身見てないんであてずっぽうだけど、まぁタブンそんなに大きくは外してないと思う。

とまぁ概算と推測なので正確性はちと怪しいが、statspackのこの項目からはJavaとOracleの通信量がおおむね1/100になっていることが伺える。このことから、実行速度の差の要因の一つは、通信の合計バイト数の差である、と言えそうである。「一つ」としたのは、通信速度の差は約24倍に対し、通信量の差は100倍あるため。通信量の差だけが原因なら、もっと速度差は付いているハズである。

Statistic なし 100
execute count 1,000,415 10,232
user calls 1,000,045 10,032

ラウンドトリップが1/100になれば、それだけOracleに対する処理依頼も1/100になるのは道理である。

ところでOracle Databaseリファレンス11gリリース2 (11.2) 統計情報の説明を見ると「execute count SQL文を実行するコール(ユーザー・コールおよび再帰コール)の合計数」「user calls ログイン、解析、フェッチ、実行などのユーザー・コールの数」とある。これを読んだ後、Javaのプログラムを見ると、バッチ更新の有無に関わらずINSERTは100万回ループしているわけで、SQL文の実行回数は100万回になりそうな気がする。しかし実際には1/100である。

これの意味は、Oracleと通信するのはJDBCだ、という所にある。直接相対するのはJDBCであって、JDBCアプリケーションではない。ものっそい簡略化した構図にすると、JDBCアプリケーション <--> JDBC <--> Oracle、となる。このことが今回カギとなるのは、JDBCアプリケーションだけを見ると100万回実行されそうだが、JDBCが1/100にしているため、それがexecute count等に現れる、という辺りにある。個人的には、statspackの統計情報はあくまでもOracle側から見た数値なのだなぁ、と実感出来たのは大きかったのでした。

Statistic なし 100
redo size 262,994,604 35,047,584

REDOログのサイズは約7倍でしかなく、100倍みたいなデカイ差はついていない。これについて現時点での俺の知識で考えられるところまでは、考えてみたい。

まず、REDOログの中身についてはREDOログに関する検証 その６ | Insight Technology, Inc.とかダンプを取れば追えるようだが、中々に複雑である。とはいえ、ざっくり構成要素を見ると、大雑把には、トランザクションに必要なチェンジベクター領域と更新データそのものの領域、となる。SQL文によってチェンジベクターのサイズがどのくらい増減するかは謎だが、更新データはそのまんま含まれるので、これを手がかりに考えたい。

通信一回ごとに発生するREDOログのサイズを考える。それぞれ、258,728,808 / 1,000,000 = 258、35,089,728 / 10,000 = 3508である。データ部分は、それぞれ20バイト、20 * 100 = 2000バイトなので、それにチェンジベクターをプラスしたら、まぁそんなくらいのサイズになるかな、といった感じ。

で、そっからデータサイズを引いた値が、データサイズを除外した1行INSERTにかかるREDOログのおおよそのサイズ、と考えられる。258 - 20 = 238、3508 - 2000 = 1508といったところ。前者は1行追加に約230バイト要し、後者は100行追加に約1500バイトとなると1行あたり15バイトで済んでいる。少なくとも、まとめてINSERTする効果がREDOログのサイズにも現れている、と考えてよさそうである。

このことから、一つ一つのINSERTのデータが極々小さい場合は、単一のREDOログにおけるチェンジベクターの割合が相対的に大きくなってしまう。その結果、1行追加にかかるコストが、まとめて100行追加するコストよりも大きくなってしまう。つまり、ごく少量のデータを小刻みにINSERTしていくと、REDOログ一つ一つのオーバーヘッドが大きくなり、実行時間の低下に繋がる、と考えられる。

最終的に同じ結果になるにも関わらず、REDOログのサイズに大きな隔たりがあるのは、なんだかんだいって個人的には驚きが大きい部分である。

Statistic なし 100
log switches (derived) 6 1
DBWR checkpoints 6 1
DBWR undo block writes 7,4262 127

REDOログのサイズが異なれば、当然それを使用する処理にも違いが現れる。バッチ更新だとログスイッチ1回が、無しだと6回で、REDOログのサイズ差がここに反映されてる形である。また、ログスイッチが起こればチェックポイントも発生していることも見て取れる。教科書知識として知っていても、実際の動作としてみると、割とあ〜なるほど〜って納得感がある。

しかし、いっこ良く分からん点がある。log_bufferは約4Mなので、たとえばバッチ更新有りだとredo sizeは約35Mなので、ログスイッチが1回で済んでるのが良く分からない。桁が1つ少ないなら分かるんで、なにかしらstatspackの見方が分かってないと思われるが、ひとまず気にしないことにする。

Statistic なし 100
undo change vector size 68,308,304 3,226,432

UNDOのサイズも違いが出てくる。これだけ差があると、ロールバックの実行時間にも影響が出るのではないか、と思われる。

Statistic なし 100
consistent gets 8,107 8,380
db block changes 2,029,652 46,383
db block gets 1,046,890 45,413
db block gets from cache 1,046,890 45,413
redo entries 1,019,822 31,350

db block changesについて。リファレンスによると「更新または削除操作の一部としてSGA内のすべてのブロックに対して行われた変更の合計数を示す。」と書かれている。ブロック数ではなく、ブロックの変更回数である。

バッチ更新無しの場合、db block changesは200万回となっている。「SGA内のすべてのブロック」は、この場合はデータベースバッファキャッシュとREDOログバッファだと思われる。それぞれに100万回アクセスが行ってると考えれば辻褄は合う。

バッチ更新有りの場合、db block changesは4.6万程度しかない。ブロックサイズは8kで、1行は20バイトちょい、20バイト * 100個 = 2000として、1回の処理でブロックの1/3〜半分くらいを埋めていると思われる。どっちにせよ1回の処理でバッファキャッシュにアクセスするブロックは1個か2個で、user callsが1万とかなので、これにプラスredo entriesでだいたいdb block changesなのかな〜と思う。

1行追加ごとに1回バッファキャッシュのブロックアクセスをするより、100行で1回*2アクセスするほうが、そりゃ早いですよね、といったところである。もちろんメモリ内での出来事なので、ちょっとやそっとの差では実行速度に差は出ないと思われるが、このケースではdb block changesが40倍なので、速度差24倍にソレナリに貢献していると考えられる。

とまぁINSERTはどっちにしろバッファキャッシュへのアクセスがあるので、ディスクにデータが追加されれば良いケースにはこれが足かせになる。これを踏まえると、バッファキャッシュを経由しないダイレクトパスインサートの位置づけが理解できる。

Latch なし 100
cache buffers chains 5,195,604 186,055
checkpoint queue latch 16,285 811
redo allocation 1,021,041 31,549
shared pool 1,002,498 11,229

ラッチ関連はこんな感じ。このエントリでは単一セッションでやっているので競合がうんぬんは関係なく、あまり重要な情報ではない。とはいえラッチを獲得するコストはゼロではないので、ここが20倍とか30倍とかになっているのも、速度差に影響していると思われる。なお、Cache Buffers Chainsラッチは日本エクセム EXEMラボ - Oracle Event Tour Scene5 ラッチ:Cache Buffers Chainsが分かりやすかった。

ソースコード＆statspackのレポート

https://github.com/kagamihoge/oraclestudy/tree/master/src/main/java/oraclestudy/fetchsize
https://github.com/kagamihoge/oraclestudy/tree/master/statspackrepots/fetchsize

参考文献＆URL

*1:http://docs.oracle.com/cd/E49329_01/network.121/b71289/sqlnet.htm#CIHJIBBI この辺変えたらまた結果変わりそうな気がする

*2:2回になることもあるだろうけど誤差と思われ