EmbulkでMySQLに大量データを投入してみる - その２

[EmbulkでMySQLに大量データを投入してみる - その１](http://qiita.com/shinyashikis@github/items/80162a252f92b3aca3a8) の続き

# エラー調査

エラーをみる感じ、一時テーブル(bulk_tbl_\*_bl_tmp*)へのデータ投入完了後、実テーブル(bulk_tbl)へマージする途中、なんらかの理由で落ちたっぽい。
そして一時テーブルをDROPしようとしてコネクションがなくなってるのでエラーになっているっぽい。

```
2015-08-05 08:35:37.456 +0900 [INFO] (transaction): Connecting to jdbc:mysql://localhost:3306/bulk_db options {user=bulk_user, tcpKeepAlive=true, useCompression=true, rewriteBatchedStatements=true, connectTimeout=300000, socketTimeout=2700000}
2015-08-05 08:35:37.672 +0900 [INFO] (transaction): SQL: INSERT INTO `bulk_tbl` (`col01`, `col02`, `col03`, `col04`, `col05`, `col06`, `col07`, `col08`, `col09`, `col10`, `col11`, `col12`, `col13`, `col14`, `col15`, `col16`, `col17`, `col18`, `col19`, `col20`) SELECT `col01`, `col02`, `col03`, `col04`, `col05`, `col06`, `col07`, `col08`, `col09`, `col10`, `col11`, `col12`, `col13`, `col14`, `col15`, `col16`, `col17`, `col18`, `col19`, `col20` FROM `bulk_tbl_0000000055c138a4090f5600_bl_tmp000` UNION ALL SELECT `col01`, `col02`, `col03`, `col04`, `col05`, `col06`, `col07`, `col08`, `col09`, `col10`, `col11`, `col12`, `col13`, `col14`, `col15`, `col16`, `col17`, `col18`, `col19`, `col20` FROM `bulk_tbl_0000000055c138a4090f5600_bl_tmp001` UNION ALL SELECT `col01`, `col02`, `col03`, `col04`, `col05`, `col06`, `col07`, `col08`, `col09`, `col10`, `col11`, `col12`, `col13`, `col14`, `col15`, `col16`, `col17`, `col18`, `col19`, `col20` FROM `bulk_tbl_0000000055c138a4090f5600_bl_tmp002` UNION ALL SELECT `col01`, `col02`, `col03`, `col04`, `col05`, `col06`, `col07`, `col08`, `col09`, `col10`, `col11`, `col12`, `col13`, `col14`, `col15`, `col16`, `col17`, `col18`, `col19`, `col20` FROM `bulk_tbl_0000000055c138a4090f5600_bl_tmp003` UNION ALL SELECT `col01`, `col02`, `col03`, `col04`, `col05`, `col06`, `col07`, `col08`, `col09`, `col10`, `col11`, `col12`, `col13`, `col14`, `col15`, `col16`, `col17`, `col18`, `col19`, `col20` FROM `bulk_tbl_0000000055c138a4090f5600_bl_tmp004` UNION ALL SELECT `col01`, `col02`, `col03`, `col04`, `col05`, `col06`, `col07`, `col08`, `col09`, `col10`, `col11`, `col12`, `col13`, `col14`, `col15`, `col16`, `col17`, `col18`, `col19`, `col20` FROM `bulk_tbl_0000000055c138a4090f5600_bl_tmp005` UNION ALL SELECT `col01`, `col02`, `col03`, `col04`, `col05`, `col06`, `col07`, `col08`, `col09`, `col10`, `col11`, `col12`, `col13`, `col14`, `col15`, `col16`, `col17`, `col18`, `col19`, `col20` FROM `bulk_tbl_0000000055c138a4090f5600_bl_tmp006` UNION ALL SELECT `col01`, `col02`, `col03`, `col04`, `col05`, `col06`, `col07`, `col08`, `col09`, `col10`, `col11`, `col12`, `col13`, `col14`, `col15`, `col16`, `col17`, `col18`, `col19`, `col20` FROM `bulk_tbl_0000000055c138a4090f5600_bl_tmp007` UNION ALL SELECT `col01`, `col02`, `col03`, `col04`, `col05`, `col06`, `col07`, `col08`, `col09`, `col10`, `col11`, `col12`, `col13`, `col14`, `col15`, `col16`, `col17`, `col18`, `col19`, `col20` FROM `bulk_tbl_0000000055c138a4090f5600_bl_tmp008` UNION ALL SELECT `col01`, `col02`, `col03`, `col04`, `col05`, `col06`, `col07`, `col08`, `col09`, `col10`, `col11`, `col12`, `col13`, `col14`, `col15`, `col16`, `col17`, `col18`, `col19`, `col20` FROM `bulk_tbl_0000000055c138a4090f5600_bl_tmp009` UNION ALL SELECT `col01`, `col02`, `col03`, `col04`, `col05`, `col06`, `col07`, `col08`, `col09`, `col10`, `col11`, `col12`, `col13`, `col14`, `col15`, `col16`, `col17`, `col18`, `col19`, `col20` FROM `bulk_tbl_0000000055c138a4090f5600_bl_tmp010` UNION ALL SELECT `col01`, `col02`, `col03`, `col04`, `col05`, `col06`, `col07`, `col08`, `col09`, `col10`, `col11`, `col12`, `col13`, `col14`, `col15`, `col16`, `col17`, `col18`, `col19`, `col20` FROM `bulk_tbl_0000000055c138a4090f5600_bl_tmp011` UNION ALL SELECT `col01`, `col02`, `col03`, `col04`, `col05`, `col06`, `col07`, `col08`, `col09`, `col10`, `col11`, `col12`, `col13`, `col14`, `col15`, `col16`, `col17`, `col18`, `col19`, `col20` FROM `bulk_tbl_0000000055c138a4090f5600_bl_tmp012` UNION ALL SELECT `col01`, `col02`, `col03`, `col04`, `col05`, `col06`, `col07`, `col08`, `col09`, `col10`, `col11`, `col12`, `col13`, `col14`, `col15`, `col16`, `col17`, `col18`, `col19`, `col20` FROM `bulk_tbl_0000000055c138a4090f5600_bl_tmp013` UNION ALL SELECT `col01`, `col02`, `col03`, `col04`, `col05`, `col06`, `col07`, `col08`, `col09`, `col10`, `col11`, `col12`, `col13`, `col14`, `col15`, `col16`, `col17`, `col18`, `col19`, `col20` FROM `bulk_tbl_0000000055c138a4090f5600_bl_tmp014` UNION ALL SELECT `col01`, `col02`, `col03`, `col04`, `col05`, `col06`, `col07`, `col08`, `col09`, `col10`, `col11`, `col12`, `col13`, `col14`, `col15`, `col16`, `col17`, `col18`, `col19`, `col20` FROM `bulk_tbl_0000000055c138a4090f5600_bl_tmp015` UNION ALL SELECT `col01`, `col02`, `col03`, `col04`, `col05`, `col06`, `col07`, `col08`, `col09`, `col10`, `col11`, `col12`, `col13`, `col14`, `col15`, `col16`, `col17`, `col18`, `col19`, `col20` FROM `bulk_tbl_0000000055c138a4090f5600_bl_tmp016` UNION ALL SELECT `col01`, `col02`, `col03`, `col04`, `col05`, `col06`, `col07`, `col08`, `col09`, `col10`, `col11`, `col12`, `col13`, `col14`, `col15`, `col16`, `col17`, `col18`, `col19`, `col20` FROM `bulk_tbl_0000000055c138a4090f5600_bl_tmp017` UNION ALL SELECT `col01`, `col02`, `col03`, `col04`, `col05`, `col06`, `col07`, `col08`, `col09`, `col10`, `col11`, `col12`, `col13`, `col14`, `col15`, `col16`, `col17`, `col18`, `col19`, `col20` FROM `bulk_tbl_0000000055c138a4090f5600_bl_tmp018` UNION ALL SELECT `col01`, `col02`, `col03`, `col04`, `col05`, `col06`, `col07`, `col08`, `col09`, `col10`, `col11`, `col12`, `col13`, `col14`, `col15`, `col16`, `col17`, `col18`, `col19`, `col20` FROM `bulk_tbl_0000000055c138a4090f5600_bl_tmp019` UNION ALL SELECT `col01`, `col02`, `col03`, `col04`, `col05`, `col06`, `col07`, `col08`, `col09`, `col10`, `col11`, `col12`, `col13`, `col14`, `col15`, `col16`, `col17`, `col18`, `col19`, `col20` FROM `bulk_tbl_0000000055c138a4090f5600_bl_tmp020` UNION ALL SELECT `col01`, `col02`, `col03`, `col04`, `col05`, `col06`, `col07`, `col08`, `col09`, `col10`, `col11`, `col12`, `col13`, `col14`, `col15`, `col16`, `col17`, `col18`, `col19`, `col20` FROM `bulk_tbl_0000000055c138a4090f5600_bl_tmp021` UNION ALL SELECT `col01`, `col02`, `col03`, `col04`, `col05`, `col06`, `col07`, `col08`, `col09`, `col10`, `col11`, `col12`, `col13`, `col14`, `col15`, `col16`, `col17`, `col18`, `col19`, `col20` FROM `bulk_tbl_0000000055c138a4090f5600_bl_tmp022` UNION ALL SELECT `col01`, `col02`, `col03`, `col04`, `col05`, `col06`, `col07`, `col08`, `col09`, `col10`, `col11`, `col12`, `col13`, `col14`, `col15`, `col16`, `col17`, `col18`, `col19`, `col20` FROM `bulk_tbl_0000000055c138a4090f5600_bl_tmp023` UNION ALL SELECT `col01`, `col02`, `col03`, `col04`, `col05`, `col06`, `col07`, `col08`, `col09`, `col10`, `col11`, `col12`, `col13`, `col14`, `col15`, `col16`, `col17`, `col18`, `col19`, `col20` FROM `bulk_tbl_0000000055c138a4090f5600_bl_tmp024` UNION ALL SELECT `col01`, `col02`, `col03`, `col04`, `col05`, `col06`, `col07`, `col08`, `col09`, `col10`, `col11`, `col12`, `col13`, `col14`, `col15`, `col16`, `col17`, `col18`, `col19`, `col20` FROM `bulk_tbl_0000000055c138a4090f5600_bl_tmp025` UNION ALL SELECT `col01`, `col02`, `col03`, `col04`, `col05`, `col06`, `col07`, `col08`, `col09`, `col10`, `col11`, `col12`, `col13`, `col14`, `col15`, `col16`, `col17`, `col18`, `col19`, `col20` FROM `bulk_tbl_0000000055c138a4090f5600_bl_tmp026` UNION ALL SELECT `col01`, `col02`, `col03`, `col04`, `col05`, `col06`, `col07`, `col08`, `col09`, `col10`, `col11`, `col12`, `col13`, `col14`, `col15`, `col16`, `col17`, `col18`, `col19`, `col20` FROM `bulk_tbl_0000000055c138a4090f5600_bl_tmp027` UNION ALL SELECT `col01`, `col02`, `col03`, `col04`, `col05`, `col06`, `col07`, `col08`, `col09`, `col10`, `col11`, `col12`, `col13`, `col14`, `col15`, `col16`, `col17`, `col18`, `col19`, `col20` FROM `bulk_tbl_0000000055c138a4090f5600_bl_tmp028` UNION ALL SELECT `col01`, `col02`, `col03`, `col04`, `col05`, `col06`, `col07`, `col08`, `col09`, `col10`, `col11`, `col12`, `col13`, `col14`, `col15`, `col16`, `col17`, `col18`, `col19`, `col20` FROM `bulk_tbl_0000000055c138a4090f5600_bl_tmp029`
2015-08-05 09:23:03.963 +0900 [ERROR] (transaction): Operation failed (0:08S01)
2015-08-05 09:23:43.490 +0900 [INFO] (main): Transaction partially failed. Cleaning up the intermediate data. Use -r option to make it resumable.
2015-08-05 09:25:03.234 +0900 [INFO] (cleanup): Connecting to jdbc:mysql://localhost:3306/bulk_db options {user=bulk_user, tcpKeepAlive=true, useCompression=true, rewriteBatchedStatements=true, connectTimeout=300000, socketTimeout=1800000}
2015-08-05 09:25:16.514 +0900 [INFO] (cleanup): SQL: DROP TABLE IF EXISTS `bulk_tbl_0000000055c138a4090f5600_bl_tmp000`
2015-08-05 09:55:37.335 +0900 [ERROR] (cleanup): Operation failed (0:08S01)
org.embulk.exec.PartialExecutionException: java.lang.RuntimeException: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
```
実際一時テーブルはDROPされず残ったままになってる。

```
mysql> show tables;
+---------------------------------------------+
| Tables_in_bulk_db                           |
+---------------------------------------------+
| bulk_tbl                                    |
| bulk_tbl_0000000055c138a4090f5600_bl_tmp001 |
| bulk_tbl_0000000055c138a4090f5600_bl_tmp002 |
| bulk_tbl_0000000055c138a4090f5600_bl_tmp003 |
| bulk_tbl_0000000055c138a4090f5600_bl_tmp004 |
| bulk_tbl_0000000055c138a4090f5600_bl_tmp005 |
| bulk_tbl_0000000055c138a4090f5600_bl_tmp006 |
| bulk_tbl_0000000055c138a4090f5600_bl_tmp007 |
| bulk_tbl_0000000055c138a4090f5600_bl_tmp008 |
| bulk_tbl_0000000055c138a4090f5600_bl_tmp009 |
| bulk_tbl_0000000055c138a4090f5600_bl_tmp010 |
| bulk_tbl_0000000055c138a4090f5600_bl_tmp011 |
| bulk_tbl_0000000055c138a4090f5600_bl_tmp012 |
| bulk_tbl_0000000055c138a4090f5600_bl_tmp013 |
| bulk_tbl_0000000055c138a4090f5600_bl_tmp014 |
| bulk_tbl_0000000055c138a4090f5600_bl_tmp015 |
| bulk_tbl_0000000055c138a4090f5600_bl_tmp016 |
| bulk_tbl_0000000055c138a4090f5600_bl_tmp017 |
| bulk_tbl_0000000055c138a4090f5600_bl_tmp018 |
| bulk_tbl_0000000055c138a4090f5600_bl_tmp019 |
| bulk_tbl_0000000055c138a4090f5600_bl_tmp020 |
| bulk_tbl_0000000055c138a4090f5600_bl_tmp021 |
| bulk_tbl_0000000055c138a4090f5600_bl_tmp022 |
| bulk_tbl_0000000055c138a4090f5600_bl_tmp023 |
| bulk_tbl_0000000055c138a4090f5600_bl_tmp024 |
| bulk_tbl_0000000055c138a4090f5600_bl_tmp025 |
| bulk_tbl_0000000055c138a4090f5600_bl_tmp026 |
| bulk_tbl_0000000055c138a4090f5600_bl_tmp027 |
| bulk_tbl_0000000055c138a4090f5600_bl_tmp028 |
| bulk_tbl_0000000055c138a4090f5600_bl_tmp029 |
+---------------------------------------------+
30 rows in set (0.00 sec)
```

コネクションタイムアウトを疑ったが、wait_connectionはデフォルトのまま8時間（28800 msec)となっているので、それが原因ではなさそう。

```
mysql> show global variables like '%timeout';
+----------------------------+----------+
| Variable_name              | Value    |
+----------------------------+----------+
| connect_timeout            | 10       |
| delayed_insert_timeout     | 300      |
| innodb_lock_wait_timeout   | 50       |
| innodb_rollback_on_timeout | OFF      |
| interactive_timeout        | 28800    |
| lock_wait_timeout          | 31536000 |
| net_read_timeout           | 30       |
| net_write_timeout          | 60       |
| slave_net_timeout          | 3600     |
| wait_timeout               | 28800    |
+----------------------------+----------+
10 rows in set (0.00 sec)
```

もう一度ログを見てみると、jdbcのコネクションタイムアウトの設定が300000ミリ秒になっている。
この状態だと、5分でコネクションが切れるのかも。

```
2015-08-05 08:35:37.456 +0900 [INFO] (transaction): Connecting to jdbc:mysql://localhost:3306/bulk_db options {user=bulk_user, tcpKeepAlive=true, useCompression=true, rewriteBatchedStatements=true, connectTimeout=300000, socketTimeout=2700000}
```

Embulkの[ソース](https://github.com/embulk/embulk-output-jdbc/blob/master/embulk-output-mysql/src/main/java/org/embulk/output/MySQLOutputPlugin.java#L91)を確認したところ、確かに300000ミリ秒を明示的に指定している。

```lang:org.embulk.output.MySQLOutputPlugin.java
props.setProperty("connectTimeout", "300000"); // milliseconds
```

そういえばEmbulk定義ファイルで [option](https://github.com/embulk/embulk-output-jdbc/tree/master/embulk-output-mysql#configuration) として設定できたので、値を7200000ミリ秒(120分)に設定してみる。

```
out:
   options: {connectTimeout: 7200000}
```

再度実行

```
$ embulk run ./sample/config.yml
```

でもエラーは変わらず。。。

もう一度さっきのログを見てみると、jdbcのソケットタイムアウトの設定が2700000ミリ秒（45分）になっている。

```
2015-08-05 08:35:37.456 +0900 [INFO] (transaction): Connecting to jdbc:mysql://localhost:3306/bulk_db options {user=bulk_user, tcpKeepAlive=true, useCompression=true, rewriteBatchedStatements=true, connectTimeout=300000, socketTimeout=2700000}
```

そういえば2700000ミリ秒ぐらいでコネクションが切れてた気がする。

```
The last packet successfully received from the server was 2,839,153 milliseconds ago.  The last packet sent successfully to the server was 2,839,151 milliseconds ago.
    at org.embulk.exec.BulkLoader$LoaderState.buildPartialExecuteException(org/embulk/exec/BulkLoader.java:331)
```

Embulkの[ソース](https://github.com/embulk/embulk-output-jdbc/blob/master/embulk-output-mysql/src/main/java/org/embulk/output/MySQLOutputPlugin.java#L92)を確認したところ、確かに2700000ミリ秒を明示的に指定している。

```lang:org.embulk.output.MySQLOutputPlugin.java
props.setProperty("socketTimeout", "2700000");   // milliseconds;
```

こちらもEmbulk定義ファイルでoptionとして7200000ミリ秒(120分)に設定してみる。

```
out:
   options: {socketTimeout: 7200000}
```

再度実行

```
$ embulk run ./sample/config.yml
```

うまくいったっぽい！！

```
mysql> select count(col01) from bulk_tbl;
+--------------+
| count(col01) |
+--------------+
|     30000000 |
+--------------+
1 row in set (5 min 30.40 sec)
```