なからなLife

geekに憧れと敬意を抱きながら、SE、ITコンサル、商品企画、事業企画、管理会計、総務・情シス、再び受託でDB屋さんと流浪する人のブログです。

MySQLへのJDBC接続で、とあるバグを踏むまでの話 -(3)古いmariadb-client-javaにて、ヤバイ動き 

3エントリに渡ってお送りしています

(1)「max_allowed_packet」の基本的な働き
(2)「Connector/J」は結構賢い
(3)古いmariadb-client-javaにて、ヤバイ動き <- イマココ

MySQL本体同様、JDBCドライバにもforkプロダクト「MariaDB Connector/J(mariadb-client-java)」があります。

mariadb.com

forkって書いたけど、connector/Jのソースからフォークしたのか、DB本体はforkしたけどJDBCドライバは別で作ったのかは、そのへんの歴史は正直知らないです、ごめんなさい。


とりあえず、同じ用に使えるってことで、MariaDB Connector/Jを使っておきながら、MySQLのDBに接続するのに、JDBC URLを「jdbc:mysql://」で書いても「jdbc:mariadb://」で書いても、ホストやポートが正しければ繋がる子です。


で、AWSさんの資料とかセミナーとか見てると、「Aurora MySQL Compatibility」に接続するJDBCドライバとしてこちらの「MariaDB Connector/J」を推す話がちらほら見かけられます。

EC2 Amazon Linuxyumリポジトリで取得できる「MariaDB Connector/J」のバージョンが古い件

jarだし、yumでいれなくても、開発したアプリで必要な他のjarと一緒にデプロイすればヨクネ?って話はともかく。

cat /etc/system-release
Amazon Linux AMI release 2018.03

yum list available | grep maria
mariadb-connector-java.noarch         1.3.6-1.5.amzn1               amzn-main

「MariaDBconnector/J 1.3.6」って、2016年2月29日リリースですよ。
https://mariadb.com/kb/en/library/mariadb-connector-j-136-release-notes/

まあ、眼の前で必要としているシステムに組み込んで動けば何でもいいwので、動かしてみます。


該当のバージョンのライブラリをmariadbのサイトから入手して、MySQL版のconnector/Jと同じスクリプトを回してみます。

Javaソースの準備

ほぼほぼ前回の流用です。

  • BulkTestMariaDB.java
import java.sql.*;

class BulkTestMariaDB{
    public static void main(String[] args) {
        String driver        = "org.mariadb.jdbc.Driver";
        String JDBC_URL      ="jdbc:mariadb://localhost";
        String JDBC_USER     = "testbulk";
        String JDBC_PASS     = "testbulk";
        String JDBC_DBNAME   = "bulk_test";

        String DATA = "";

        int COUNT       = 50000; // total insert record
        int BATCH_SIZE  =  1000; // bulk per insert
        int COMMIT_SIZE = 10000;

        String BULK_MODE = "true";

        int STR_LENGTH = 1000;
        for (int i = 1; i <= STR_LENGTH; i++) {
            DATA = DATA + "a";
        }
        try{
            Class.forName (driver);

            Connection conn = DriverManager.getConnection(JDBC_URL + "/" + JDBC_DBNAME + "?rewriteBatchedStatements=" + BULK_MODE,JDBC_USER, JDBC_PASS);
            conn.setAutoCommit(false);

            // テーブルの初期化
            Statement stmt = conn.createStatement ();
            String sql = "TRUNCATE TABLE loadtest";
            ResultSet rs = stmt.executeQuery (sql);

            // BulkInsertTest本体
            PreparedStatement pstmt = conn.prepareStatement("insert into loadtest (id, data1,data2) values (?, ?, ?)");
            for (int i = 1; i <= COUNT; i += BATCH_SIZE) {
                pstmt.clearBatch();
                for (int j = 0; j < BATCH_SIZE; j++) {
                    pstmt.setInt(1, i + j);

                    if (j == 530) {
                        pstmt.setString(2, DATA);
                        pstmt.setString(3, "b");
                    }else{
                        pstmt.setString(2, DATA);
                        pstmt.setString(3, DATA);
                    }
                    pstmt.addBatch();
                }
                pstmt.executeBatch();
                if ((i + BATCH_SIZE - 1) % COMMIT_SIZE == 0) {
                    conn.commit();
                }
            }
            conn.commit();
       } catch (SQLException e) {
            System.err.println("SQL failed.");
            e.printStackTrace ();
        } catch (ClassNotFoundException ex) {
            ex.printStackTrace ();
        }
    }
}
コンパイル&実行

こちらも前回と同じ条件で、MariaDBのConnector/J版を用意。

  • BulkTestMySQLCompileAndRun.sh
javac BulkTestMariaDB.java
export CLASSPATH=./mariadb-java-client-1.3.6.jar:.
java BulkTestMariaDB

実際にJDBC経由でバルクインサートを実行してみる。

まずは、デフォルトの状態から。

mysql -u testbulk -p -e "select @@global.max_allowed_packet, @@global.net_buffer_length"
+-----------------------------+----------------------------+
| @@global.max_allowed_packet | @@global.net_buffer_length |
+-----------------------------+----------------------------+
|                     4194304 |                      16384 |
+-----------------------------+----------------------------+

./BulkTestMySQLCompileAndRun.sh

mysql -u testbulk -p -D bulk_test -e "select count(*) from loadtest;select length(data1),length(data2) from loadtest limit 10;"
+----------+
| count(*) |
+----------+
|    50000 |
+----------+
+---------------+---------------+
| length(data1) | length(data2) |
+---------------+---------------+
|          1000 |          1000 |
|          1000 |          1000 |
|          1000 |          1000 |
|          1000 |          1000 |
|          1000 |          1000 |
|          1000 |          1000 |
|          1000 |          1000 |
|          1000 |          1000 |
|          1000 |          1000 |
|          1000 |          1000 |
+---------------+---------------+

問題なく、動きました。

max_allowed_packetを小さくしてみる

1MBまで小さくして、同じソースを実行してみます。

service mysqld stop
mysqld を停止中:                                           [  OK  ]
service mysqld start
mysqld を起動中:                                           [  OK  ]

mysql -u root -p -e "set @@global.max_allowed_packet = 1048576"

mysql -u testbulk -p -e "select @@global.max_allowed_packet, @@global.net_buffer_length"
+-----------------------------+----------------------------+
| @@global.max_allowed_packet | @@global.net_buffer_length |
+-----------------------------+----------------------------+
|                     1048576 |                      16384 |
+-----------------------------+----------------------------+

/BulkTestMariaDBCompileAndRun.sh
SQL failed.
java.sql.BatchUpdateException: Duplicate entry '531' for key 'PRIMARY'
        at org.mariadb.jdbc.MariaDbStatement.executeBatch(MariaDbStatement.java:1261)
        at BulkTestMariaDB.main(BulkTestMariaDB.java:50)
Caused by: java.sql.SQLIntegrityConstraintViolationException: Duplicate entry '531' for key 'PRIMARY'
        at org.mariadb.jdbc.internal.util.ExceptionMapper.get(ExceptionMapper.java:119)
        at org.mariadb.jdbc.internal.util.ExceptionMapper.throwException(ExceptionMapper.java:69)
        at org.mariadb.jdbc.MariaDbStatement.executeQueryEpilog(MariaDbStatement.java:259)
        at org.mariadb.jdbc.MariaDbStatement.execute(MariaDbStatement.java:323)
        at org.mariadb.jdbc.MariaDbStatement.executeBatch(MariaDbStatement.java:1239)
        ... 1 more
Caused by: org.mariadb.jdbc.internal.util.dao.QueryException: Duplicate entry '531' for key 'PRIMARY'
        at org.mariadb.jdbc.internal.protocol.AbstractQueryProtocol.getResult(AbstractQueryProtocol.java:479)
        at org.mariadb.jdbc.internal.protocol.AbstractQueryProtocol.result(AbstractQueryProtocol.java:400)
        at org.mariadb.jdbc.internal.protocol.AbstractQueryProtocol.executeQuery(AbstractQueryProtocol.java:365)
        at org.mariadb.jdbc.MariaDbStatement.execute(MariaDbStatement.java:316)
        ... 2 more


落ちた!しかも「 Duplicate entry '531' for key 'PRIMARY'」って、主キーの重複違反!

ロジック上、どうやっても主キー重複が発生しないはずなんですけど。。。

何が起こっているかの確認:SHOW STATUS

さっき、再起動してSHOW STATUSのカウンタもリセットしてありますので、さっそくCom_insertの値を見てみます。

mysql -u testbulk -p -e "show global status like 'Com_insert';"
Enter password:
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Com_insert    | 2     |
+---------------+-------+

エラーが起きた番号が531ですし、前回のMySQL Connector/Jと同じ挙動ならば、1,000件ずつのバルクインサートをJDBCドライバが2回に分けて発行した、その2回目にいる番号なので、そんなもんですね。

しかし、なぜ、2回目の531番が主キー違反で落ちるのか。。。


何が起こっているかの確認:General Log

前回同様、MySQL Workbenchで探りを入れてみます。

1回目の最後に、
f:id:atsuizo:20180926134218p:plain


?519のあと、531が入っている!

2回目の最初に、
f:id:atsuizo:20180926134236p:plain


?521から始まってる!520はドコ?!


更に進むと、
f:id:atsuizo:20180926134254p:plain

531がもう1回来てる!


そりゃ、主キー違反になりますがな。


平たく言うと、前回まとめで書いた機能

  • MySQL Connector/Jは、バルクインサート文を自動で構築してくれる機能がある。
  • MySQL Connector/Jは、バルクインサート文自動生成機能では、max_allowed_packetの設定に合わせて、バルクインサートのSQL文の大きさを調整してくれる。

がバグってます。

ここでカラク

前回のJavaソース読んで気づいた人がいるかも知れませんが、531だけ、わざと格納する文字列を短くしてます。通常「a」が1,000個ですが、data2列に入れる文字列を「b」1個だけにしました。

コレ、531番目も同じようにdata2列に「a」を1,000個入れるロジックだと落ちないんです。

いまはテストデータですが、リアルに開発するとき、バルクで取り込むデータの長さってレコードによってまちまちであることのほうが普通ですから、それを模して、長さの違うデータを意図的にインサートさせるためにやってみたものです。

どうやら、mariadb-connector/Jの場合

  • バルクインサート文自動生成機能では、max_allowed_packetの設定に合わせて、バルクインサートのSQL文の大きさを調整してくれる。
  • バルクインサート文の自動生成時、max_allowed_packet値に近づくと、より後方にあるデータで短くて詰め込めそうなものを探して「飛び級?」で入れている。
  • しかし、飛び級?によってスキップしたレコードの一部を失ったり、飛び級したレコードを二重登録してしまう、という不具合が「1.3.6」には潜んでいる。

ってことのようです。


いまはテストデータですが、リアルに開発するとき、バルクで取り込むデータの長さってレコードによってまちまちであることのほうが一般的ですから、このバグを踏む可能性ってフツーにあるわけですね。

最新だとバグってない。

前回エントリで使用した「MySQLのConnector/J」は「5.1.47 (2018-08-17)」と、比較的あたらしいものでした。
古いのと新しいのを比較して、どっちが優れているとか言っても仕方がないですね。MariaDB connector/Jの最新は「2.3.0 (2018-09-07)」で試したところ、この問題は発生しませんでした。


なので、安心して新しいやつを使っていただければと思います。



が、バグレポが見つからない。。。レポが見つからないので、いつFixしたのかもわからない。

とりあえず、力技で、いつ治ったのか探してみました。

1つずつ、バージョンを上げていったところ、トンデモナイやつがいた。

とりあえず、1つ上のもの「1.3.7」を入手して、これを使って実行したら、衝撃の結末が待っていました。

  • BulkTestMySQLCompileAndRun.sh
javac BulkTestMariaDB.java
#export CLASSPATH=./mariadb-java-client-1.3.6.jar:.
export CLASSPATH=./mariadb-java-client-1.3.7.jar:.
java BulkTestMariaDB
./BulkTestMariaDBCompileAndRun.sh

mysql -u testbulk -p -D bulk_test -e "select count(*) from loadtest;select length(data1),length(data2) from loadtest limit 10;"
Enter password:
+----------+
| count(*) |
+----------+
|    25910 |
+----------+
+---------------+---------------+
| length(data1) | length(data2) |
+---------------+---------------+
|          1000 |          1000 |
|          1000 |          1000 |
|          1000 |          1000 |
|          1000 |          1000 |
|          1000 |          1000 |
|          1000 |          1000 |
|          1000 |          1000 |
|          1000 |          1000 |
|          1000 |          1000 |
|          1000 |          1000 |
+---------------+---------------+

エラーが出ない!

でも、件数が正しくない!


細かいログは示しませんが、調べた結果、以下のことが起きていました。

  • 1~9999(4桁以下)

各1~519だけ実行、520以上はINSERT文が来ていない。

  • 10000~50000(5桁)

各1~518だけ実行、519以上はINSERT文が来ていない。

  • 結果
番号帯 件数/インサート インサート回数 小計
1~9999 519件 10回 5190件
10000~50000 518件 40回 20720件
合計 50回 25910件


ひどい。。。せめてエラーになってくれ。エラーにならずに、データ欠落した状態でインサート成功!(キリッ はヤバいでしょ。


が、列に対する桁溢れを切り捨てて平気な顔をしているMySQLらしさに溢れてる、といえなくもない。(後述するが、本家にはこのバグはない模様)




こんな調査を進めていった結果、以下のようになりました。

MariaDB Connector/J Version Date バルクインサートの挙動
1.3.5 2016-02-09 分割バグによる主キー違反発生
1.3.6 2016-02-29 分割バグによる主キー違反発生
1.3.7 2016-03-23 分割の後半がINSERTされない
1.4.0 2016-04-01 分割の後半がINSERTされない
1.4.1 2016-04-11 正しく分割&正しく格納


2年以上前のバージョンの挙動差異の確認とか、なにそれ考古学の世界かよ。

追記

1.4.1(ていうか1.4.0~1.4.2)は、別のバグが"Blocker"で報告されています。少なくとも1.4.3までは引き上げる必要があります。
そして、1.4.2~2.2.0RCに影響のあるバグ(古いものには影響がない!)も見つかります。他のバグも含めて、要注意ですね。

じゃあ、同時期のMySQL公式Connector/Jはどうなんだ?

同時期のものを調べてみる
MySQL Connector/J Version Date バルクインサートの挙動
5.1.37 2015-10-15 正しく分割&正しく格納
5.1.38 2015-12-07 正しく分割&正しく格納
5.1.39 2016-05-09 正しく分割&正しく格納
5.1.40 2016-10-03 正しく分割&正しく格納
5.1.41 2017-02-28 正しく分割&正しく格納

問題なし。

激しく古いヤツを調べてみる。

MySQL本家のConnector/Jが「rewriteBatchedStatements」をサポートしたのは、リファレンスを見ると「Since version: 3.1.13(2006-05-26)」ってことなので、当初どうだったのか調べてみる。

MySQL Connector/J Version Date バルクインサートの挙動
3.1.13 2006-05-26 バルクインサートしてない!


まさかの、バルクインサートしてない!という。


こうなったら、rewriteBatchedStatementsでバルクインサートをサポートした時期がいつなのか、探してやる。

MySQL Connector/J Version Date バルクインサートの挙動
3.1.13 2006-05-26 バルクインサートしてない
3.1.14 2006-10-19 バルクインサートしてない
5.0.0 2005-12-22 (入手できず)
5.0.1 2005-12-22 (入手できず)
5.0.2 2006-07-11 (入手できず)
5.0.3(Beta) 2006-07-26 バルクインサートしてない
5.0.4 2006-10-20 バルクインサートしてない
5.0.5 2007-03-02 正しく分割&正しく格納

見つかりました。


サポートした途端、バグなしで動いています。


で、5.0.5のリリースノートを読んでみたのですが、書いてねえ。。。。
MySQL :: MySQL Connector/J 5.1 Release Notes :: Changes in MySQL Connector/J 5.0.5 (2007-03-02)


ドキュメントの読み込みが甘いかもしれないけど、最新のリファレンスにもそんな機能があるって書いてないし、さもありなん。


まとめ

  • MySQL Connector/Jは、バルクインサート文を自動で構築してくれる機能がある。
  • MySQL互換のMariaDBも、MariaDBconnector/Jを提供していて、同じバルク対応機能もある。
  • MariaDBconnector/J(mariadb-client-java)の古いバージョン(1.4.0以前)には、バグがある。
  • 本家MySQL Connector/JでrewriteBatchedStatementsパラメータが追加されたのは3.1.13(2006-05-26)からだが、このときexecuteBatch()バルクインサート自動生成機能は未対応。
  • 本家MySQL Connector/Jでバルクインサート文を自動で構築してくれる機能は、5.0.5(2007-03-02)から。なお、このバージョンにバグはない。


以上、MySQL&MariaDB Connector/J考古学でした?

最後に

JDBCドライバがバルクインサート文を自動生成してくれる、ってなかなかすごい機能だな、と思いました。
プログラマが意図してexecuteBatchを発行した単位をガン無視して、max_allowed_packetを超えないように丸めて分割してバルクインサート文作ってる、なかなか豪快な機能です。
バグを踏んでない限りエラーにならないから、裏でこんな動きをしているとか、フツーは意識しないよね。


バグは世の常なので、まあ、仕方ないよね。このバグが絡んでるあたりのMariaDB Connector/Jのリリース頻度、10日刻みとかですし、改善されていってるのをひしひしと感じます。


ただし、ドライバは、なるべく新しいものを使おう!


おまけ

Connector/Jでのバルクインサート文の自動生成は、「max_allowed_packet」だけを基準にしています。


なので、

  • net_buffer_length => max_allowed_packetの場合、net_buffer_lengthが1SQLの上限値になる。
  • net_buffer_length < max_allowed_packetの場合、max_allowed_packetが1SQLの上限値になる。

MySQLへのJDBC接続で、とあるバグを踏むまでの話 -(1)「max_allowed_packet」の基本的な働き - なからなLife

は適用されません。ご注意を。

追記

executeBatch()でmax_allowed_packetのサイズに収まるように分解してくれるんだけど、そもそも1件でmax_allowed_packetに収まらないようなデータをaddして実行すると、そこで「 java.sql.BatchUpdateException: Could not send query」で落ちます。

あたりまえといえば、あたりまえか。



実践ハイパフォーマンスMySQL 第3版

実践ハイパフォーマンスMySQL 第3版