MySQL Connector/Jでプロパティをあれこれ変えてベンチマークその1：バッチ編

**[MySQL Casual Advent Calendar](https://qiita.com/advent-calendar/2017/mysql-casual)**初参戦記事、その1です。

昨日は@atsuizoさんの [SELECT文をタイムアウト強制終了させる「MAX_EXECUTION_TIME」使ってる？](http://atsuizo.hatenadiary.jp/entry/2017/12/09/000000) でした。

私の記事は内容のわりに長くなりそうなので、読むのにツラくならないよう、3週に分けてお送りします。

# 0. 検証環境

Casualにやる、ということで、サーバに持って行くのをやめて、PCのIDE上でさらっと実行してみます。
そのため、環境が変わると結果がかなり変わるはずです。

 * PCのスペックなど

![pc_spec.png](https://qiita-image-store.s3.amazonaws.com/0/123899/be91ec40-c631-94fd-3089-3fa948121da5.png)

 * IDE : Eclipse 4.7.1a（pleiades日本語化）
 * MySQL Community Server : Windows（x64）版 5.7.20
 * MySQL Connector/J : 5.1.44（Mavenリポジトリより取得）

　※執筆時点で1つ古いヤツですが…。

 * `my.ini`

```text:my.ini
[mysqld]
basedir = C:\\dev\\mysql-5.7.20-winx64
datadir = C:\\dev\\mysql-5.7.20-winx64\\data
tmpdir = C:\\dev\\mysql-5.7.20-winx64\\tmp

max_connections = 30

explicit_defaults_for_timestamp = 1

innodb_buffer_pool_size = 4G
innodb_log_file_size = 1G
innodb_status_output = 1
innodb_status_output_locks = 1

character_set_server = utf8
collation_server = utf8_general_ci

general_log = 1
general_log_file = C:\\dev\\mysql-5.7.20-winx64\\logs\\general_query_all.log
log_error = C:\\dev\\mysql-5.7.20-winx64\\logs\\mysqld_error.log
log_queries_not_using_indexes = 1
log_slow_admin_statements = 1
log_syslog = 0
log_timestamps = SYSTEM
long_query_time = 3
slow_query_log = 1
slow_query_log_file = C:\\dev\\mysql-5.7.20-winx64\\logs\\slow_query.log

[mysql]
default-character-set = utf8
show-warnings

prompt = "\u@\h [\d] > "
```

　※Windows版に慣れていないので、**[MySQL Community Server 5.7.19 - Installing on Windows 10](https://qiita.com/rubytomato@github/items/15ec40069f2eec57b25f)（@rubytomato@githubさん）** を参考にしました。ありがとうございます。

# 1. 検証内容

MySQL Connector/Jで、性能に関わるプロパティにはいくつかあります。

 * **[5.1 Driver/Datasource Class Names, URL Syntax and Configuration Properties for Connector/J](https://dev.mysql.com/doc/connector-j/5.1/en/connector-j-reference-configuration-properties.html)（MySQL Connector/J 5.1 Developer Guide）**

　※主に、ページ中盤あたりからの **Performance Extensions.** を参照。

このうち、複数レコードを一括`INSERT`する処理がある場合に真っ先に思い浮かぶのが `rewriteBatchedStatements` だと思います。

 * **[MySQL Connector/Jにおける大量INSERTのチューニング](http://d.hatena.ne.jp/sh2/20090528)（SH2の日記）**

でも取り上げられている定番項目ですが、

 * `rewriteBatchedStatements` を有効にし忘れた場合、どうなる？
 * 先のSH2さんの記事では**「100レコードずつ`INSERT`し1,000レコード毎に`COMMIT`」**しているが、この単位を変えるとどうなる？
 * 複数スレッドで実行した場合の変化は？

の3点について検証してみます。

# 2. 検証結果

検証コードやDB・テーブル定義等は最後のほうに掲載します。
Java検証コード実行時の引数に、

 * 非バッチ`INSERT`（`VALUES`連結なし）スレッドの実行数
 * バッチ`INSERT`（`VALUES`連結あり）スレッドの実行数
 * `INSERT`行数
 * バッチ`INSERT`時の`VALUES`連結単位（行数）
 * `COMMIT`単位（行数）
 * MySQL Connector/J URLオプションパラメータ（プロパティを指定）

を指定する形で、「非バッチ`INSERT`スレッド→バッチ`INSERT`スレッド」の順に、開始を1秒ずつ遅らせながらスレッドを実行していき、各スレッドの所要時間を計測しました。

※表中の値（ミリ秒）は「5回実行したうちの最大値と最小値を除いた平均値」を示しています。

## 2-1. `rewriteBatchedStatements` を有効にし忘れた場合、どうなる？

これ、身近なところで実際にあった（やっちまった）事例の1つです。

 * バッチ`INSERT`（`addBatch`→`executeBatch`）で `rewriteBatchedStatements` **無効**時

を、

 * 非バッチ`INSERT`（`execute()`）時
 * バッチ`INSERT`（`addBatch()`→`executeBatch()`）で `rewriteBatchedStatements` **有効**時

と比較します。

なお、`INSERT`行数は20万行、バッチ`INSERT`の単位は100行、`COMMIT`単位は1,000行で固定します。1スレッドでの実行です。

| 検証パターン | 所要時間 (ms) |
|:--|--:|
| バッチ・`rewriteBatchedStatements` 無効 | 49,115 |
| 非バッチ | 84,231 |
| バッチ・`rewriteBatchedStatements` 有効 | 19,845 |

`rewriteBatchedStatements` 有効の倍以上の時間が掛かる一方、非バッチよりは速いため、**「`rewriteBatchedStatements` の指定忘れに気づかない」**という落とし穴があります（体験談）。気を付けましょう。

## 2-2. `INSERT`・`COMMIT`単位を変えるとどうなる？

 * バッチ**`INSERT`100行**単位／**`COMMIT`1,000行**単位
 * バッチ**`INSERT`1,000行**単位／**`COMMIT`1,000行**単位
 * バッチ**`INSERT`1,000行**単位／**`COMMIT`10,000行**単位

の3パターンで実行します（`INSERT`行数は20万行、`rewriteBatchedStatements` は有効）。

| 検証パターン | 所要時間 (ms) |
|:--|--:|
| バッチ100／`COMMIT`1,000 | 19,845 |
| バッチ1,000／`COMMIT`1,000 | 4,464 |
| バッチ1,000／`COMMIT`10,000 | 3,385 |

SH2さんの記事では**「増やしても伸びない」**旨の記述がありましたが、さすがに時代が変わったせいか、もっと伸びるようです（`INSERT`する内容にもよると思いますが）。
但し、書き替え行数の単位が大きくなると**Heapメモリ不足**がちらついてきますので、その点についてはご注意を。

また、`INSERT`だけでなく`UPDATE`や`DELETE`が絡む場合はロックによる速度低下やデッドロックにも注意、です。

## 2-3. 複数スレッドで実行した場合の変化は？

1スレッドだけ高速になっても、他のスレッドに影響が出ては…ということで試してみました。
まずは**4スレッド並行**で、**バッチ：非バッチの比率を変えながら**検証してみます。

※スレッドあたり`INSERT`行数20万行／バッチ`INSERT`1,000行単位／`COMMIT`10,000行単位／`rewriteBatchedStatements` 有効で。

| 検証パターン | バッチ所要時間 (ms) | 非バッチ所要時間 (ms) |
|:--|--:|--:|
| バッチ1：非バッチ3 | 6,974 | 38,753 |
| バッチ2：非バッチ2 | 5,814 | 35,005 |
| バッチ3：非バッチ1 | 5,131 | 42,453 |

バッチ`INSERT`スレッドについては、**バッチが増える＝非バッチが減るほど高速化**しています。
一方、非バッチ`INSERT`スレッドは、**スレッド数がバッチ＞非バッチとなった時に遅く**なっています。

次に、**8スレッド並行**で検証してみます（`INSERT`行数等は先ほどと同じ）。

| 検証パターン | バッチ所要時間 (ms) | 非バッチ所要時間 (ms) |
|:--|--:|--:|
| バッチ1：非バッチ7 | 22,398 | 85,643 |
| バッチ3：非バッチ5 | 15,025 | 64,833 |
| バッチ5：非バッチ3 | 11,508 | 45,332 |
| バッチ7：非バッチ1 | 7,926 | 47,137 |

バッチ`INSERT`スレッドについては、先ほどと同様に**バッチが増える＝非バッチが減るほど高速化**しています。
非バッチ`INSERT`スレッドは、**スレッド数が1のときだけ遅く**なっています。
但し、**落ち込みはわずか**です。

# 3. まとめ

 * `addBatch()`＋`executeBatch()` するときは `rewriteBatchedStatements=true` を忘れずに
 * メモリ不足などに気を付ける必要はあるが、`addBatch()`＋`executeBatch()` は（更新系が`INSERT`のみの場合）ある程度他のスレッドのことを気にせずに積極的に使ってしまってもいいかもしれない

[次回（12/17）の記事](https://qiita.com/hmatsu47/items/90bbe12a3082ca312017)では、その他のプロパティ（主に接続時の環境確認などのために発行されるクエリの数を抑制するためのもの）を検証してみます。

なお、ちょっとだけフライングで結果を示すと、

 * `rewriteBatchedStatements=true&characterEncoding=utf8&characterSetResults=utf8&alwaysSendSetIsolation=false&elideSetAutoCommits=true&useLocalSessionState=true&cacheServerConfiguration=true`

としたときの結果（8スレッド／バッチ7：非バッチ1、プロパティ以外は最後のテストケースと同条件）は、**「バッチ7,581ms／非バッチ33,145ms」**でした。

明日は@tom--boさんの [MySQL(innodb)の分離レベルごとのanomalyについて実験した](http://tombo2.hatenablog.com/entry/2017/12/11/141156) です。

# 4. 検証に使ったコードなど

```xml:pom.xml
<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
  <modelVersion>4.0.0</modelVersion>
  <groupId>ConJTest</groupId>
  <artifactId>ConJTest</artifactId>
  <version>0.0.1-SNAPSHOT</version>
  <build>
    <sourceDirectory>src</sourceDirectory>
    <plugins>
      <plugin>
        <artifactId>maven-compiler-plugin</artifactId>
        <version>3.7.0</version>
        <configuration>
          <source>1.8</source>
          <target>1.8</target>
        </configuration>
      </plugin>
    </plugins>
  </build>
  <dependencies>
  	<dependency>
  		<groupId>mysql</groupId>
  		<artifactId>mysql-connector-java</artifactId>
  		<version>5.1.44</version>
  	</dependency>
  </dependencies>
</project>
```

```java:DbConnection.java
package site.hmatsu47.conjtest;
import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.SQLException;

public class DbConnection {

	private static final String DRIVER_NAME	= "com.mysql.jdbc.Driver";
	private static final String JDBC_USER	= "testuser";
	private static final String JDBC_PASS	= "T35+U53r";

	public Connection getConnectionForTest(String url) throws ClassNotFoundException, SQLException {
		Class.forName(DRIVER_NAME);
		return DriverManager.getConnection(url, JDBC_USER, JDBC_PASS);
	}
}
```

```java:DbInsert.java
package site.hmatsu47.conjtest;
import java.sql.Connection;
import java.sql.PreparedStatement;
import java.sql.SQLException;

public class DbInsert {

	private static final String JDBC_URL	= "jdbc:mysql://testdb:3306/insert_test";
	private static final String TEST_MEMO	= "1234567890１２３４５６７８９０1234567890１２３４５６７８９０1234567890１２３４５６７８９０1234567890１２３４５６７８９０1234567890１２３４５６７８９０";

	public void batchInsert(int totalline, int batchline, int commitline, String option) {

		try (
			Connection 			con		= new DbConnection().getConnectionForTest(JDBC_URL + option);
			PreparedStatement	psmt	= con.prepareStatement("INSERT INTO insert_test.insert_test (memo) VALUES (?)")
		) {
			con.setAutoCommit(false);
			psmt.clearBatch();

			for (int i = 1; i <= totalline; i++) {
				psmt.setString(1, TEST_MEMO);
				psmt.addBatch();

				if ((i % batchline == 0) || (i == totalline)) {
					psmt.executeBatch();
					psmt.clearBatch();

					if ((i % commitline == 0) || (i == totalline)) {
						con.commit();
					}
				}
			}
		} catch (ClassNotFoundException e) {
			System.out.println("[Error] Driver not found.");
			e.printStackTrace();
		} catch (SQLException e) {
			System.out.println("[Error] Invalid DB access.");
			e.printStackTrace();
		}
	}

	public void simpleInsert(int totalline, int commitline, String option) {

		try (
			Connection 			con		= new DbConnection().getConnectionForTest(JDBC_URL + option);
			PreparedStatement	psmt	= con.prepareStatement("INSERT INTO insert_test.insert_test (memo) VALUES (?)")
		) {
			con.setAutoCommit(false);

			for (int i = 1; i <= totalline; i++) {
				psmt.setString(1, TEST_MEMO);
				psmt.execute();

				if ((i % commitline == 0) || (i == totalline)) {
					con.commit();
				}
			}
		} catch (ClassNotFoundException e) {
			System.out.println("[Error] Driver not found.");
			e.printStackTrace();
		} catch (SQLException e) {
			System.out.println("[Error] Invalid DB access.");
			e.printStackTrace();
		}
	}
}
```

```java:SimpleInsert.java
package site.hmatsu47.conjtest;

public class SimpleInsert extends Thread {

	private int 	totalline	= 0;
	private int 	commitline	= 0;
	private String option;
	private String title;

	public SimpleInsert(int totalline, int commitline, String option, String title) {
		this.totalline	= totalline;
		this.commitline	= commitline;
		this.option		= option;
		this.title		= title;
	}

	public void run() {
		long	starttime	= System.nanoTime();

		new DbInsert().simpleInsert(totalline, commitline, option);

		long	endtime	= System.nanoTime();

		System.out.println("[Simple] " + title + " : " + String.valueOf((endtime - starttime) / (1000 * 1000)) + " msec.");
	}
}
```

```java:BatchInsert.java
package site.hmatsu47.conjtest;

public class BatchInsert extends Thread {

	private int 	totalline	= 0;
	private int 	batchline	= 0;
	private int 	commitline	= 0;
	private String option;
	private String title;

	public BatchInsert(int totalline, int batchline, int commitline, String option, String title) {
		this.totalline	= totalline;
		this.batchline	= batchline;
		this.commitline	= commitline;
		this.option		= option;
		this.title		= title;
	}

	public void run() {
		long	starttime	= System.nanoTime();

		new DbInsert().batchInsert(totalline, batchline, commitline, option);

		long	endtime	= System.nanoTime();

		System.out.println("[Batch]  " + title + " : " + String.valueOf((endtime - starttime) / (1000 * 1000)) + " msec.");
	}
}
```

```java:Main.java
package site.hmatsu47.conjtest;

public class Main {

	private static final int		DEFAULT_SIMPLE_THREAD	= 0;
	private static final int		DEFAULT_BATCH_THREAD		= 1;
	private static final int		DEFAULT_TOTAL_LINE		= 1000000;
	private static final int		DEFAULT_BATCH_LINE		= 100;
	private static final int		DEFAULT_COMMITL_LINE		= 1000;
	private static final String	DEFAULT_JDBC_OPTION		= "";

	public static void main(String args[]) {
		try {
			final int		simplethread	= (args.length < 1 ? DEFAULT_SIMPLE_THREAD : Integer.valueOf(args[0]).intValue());
			final int		batchthread	= (args.length < 2 ? DEFAULT_BATCH_THREAD : Integer.valueOf(args[1]).intValue());
			final int		totalline		= (args.length < 3 ? DEFAULT_TOTAL_LINE : Integer.valueOf(args[2]).intValue());
			final int		batchline		= (args.length < 4 ? DEFAULT_BATCH_LINE : Integer.valueOf(args[3]).intValue());
			final int		commitline		= (args.length < 5 ? DEFAULT_COMMITL_LINE : Integer.valueOf(args[4]).intValue());
			final String	option			= (args.length < 6 ? DEFAULT_JDBC_OPTION : args[5]);

			for (int i = 1; i <= simplethread; i++) {
				SimpleInsert si = new SimpleInsert(totalline, commitline, option, String.valueOf(i));
				si.start();
				Thread.sleep(1000);
			}

			for (int i = 1; i <= batchthread; i++) {
				BatchInsert bi = new BatchInsert(totalline, batchline, commitline, option, String.valueOf(i));
				bi.start();
				Thread.sleep(1000);
			}
		}
		catch (Exception e) {
			System.out.println("[Error]");
			e.printStackTrace();
		}
	}
}
```

```mysql:ユーザ・DB・テーブル定義
root@localhost [(none)] > CREATE USER 'testuser'@'localhost' IDENTIFIED BY 'T35+U53r';
Query OK, 0 rows affected (0.00 sec)

root@localhost [(none)] > GRANT SELECT, INSERT, UPDATE, DELETE ON *.* TO 'testuser'@'localhost';
Query OK, 0 rows affected (0.00 sec)

root@localhost [(none)] > CREATE DATABASE insert_test;
Query OK, 1 row affected (0.01 sec)

root@localhost [(none)] > USE insert_test;
Database changed

root@localhost [insert_test] > CREATE TABLE insert_test (id INT UNSIGNED PRIMARY KEY AUTO_INCREMENT, memo VARCHAR(200)) ENGINE InnoDB DEFAULT CHARSET=utf8mb4;
Query OK, 0 rows affected (0.13 sec)
```