【AD】フリーランスを応援します

何度か本ブログでも取り上げていますが、自分の腕で生き抜いていきたいと考えているエンジニアほど、独立すべきだと思っています。

とはいえ不安、何をどうしたら良いかわからない。など悩みは尽きないと思います。

そんなあなたに、とりあえず相談してみることからオススメします。
今の仕事をすぐ変える必要はなく、リスク無しでフリーランスのライフスタイルを明確にすることができます。

私のオススメは断然下記の「株式会社レバレジーズ」です。
取り扱っている案件数が豊富で、フリーランス界隈では実績も豊富でサポート体制も充実しております。



独立を考えているエンジニアの方は、まずは登録してお話を伺ってみてはいかがでしょうか?


scalikejdbcでmysqlとの通信時のCommunicationsExceptionに対処する

概要

scalaアプリケーションを作成している際に下記のような例外が発生しているケースがありました。

[CommunicationsException: Communications link failure

The last packet successfully received from the server was 15,048 milliseconds ago.  The last packet sent successfully to the server was 10 milliseconds ago.]

今回はこのエラーの原因とその対処についてまとめたいと思います。
ちなみにタイトルにはscalikejdbcと記述してありますが、原因分析についてはmysqlを使用していれば例外なくほぼ同じことが原因であることが多いです。
またアプリケーションについてもscalaといわず、javaを用いていれば同じような対応で解決できます。
(言わずともscalaってjavaのラッパーみたいなものなので)

また私の環境ではscalikejdbcというライブラリを使用したコネクションプールを使っており、検証にそれを用いることとしますし、特にその点については詳しく述べます。

原因

初めに原因だけ端的に記述しておきましょう。
原因としてはアプリケーションが確立したmysqlとの接続、いわゆる「コネクション」が途切れているにもかかわらずアプリケーションではその使えなくなったコネクションを利用してmysqlとの通信をしようとしているからである。

ネットなどで検索するとよくあるのが、一日立ってからアプリケーションが動き出そうとしたタイミングで一回だけ発生する。などの記述が少なくない。

これはアプリケーション(クライアント)が認識しているコネクションの有効性と、mysql(サーバ)が認識しているコネクションの有効性が食い違っているからである。

クライアントでは通常一度作成したコネクションに関してそのまま使い回す。
サーバでは一度作成されたコネクションをいつまでも有効にしていると、新しいクライアントとのコネションを作成する際の邪魔になってしまう。
そのため一定時間アイドル状態(通信が発生していない)であったコネクションをクローズする仕組みが存在する。

そのためサーバ側では閉じたはずのコネクションに対して、クライアントから通信が行われ、結果通信ができずエラーとなるのである。

コネクションプール

さて更にここで掘り下げてコネクションプールを用いている場合にはどうなっているのかということについてより詳しく記述する。
私の環境ではscalikejdbcというライブラリのコネクションプール機能を利用しているが、まあ他のアプリケーションでもコネクションプールを利用している場合はそんなに変わらないでしょう。

コネクションプールとはコネクションを確立する際のコストを減らすため、予め確立しておいたコネクションをすぐに使えるように準備する(プールする、という)仕組みである。

コネクションプールを用いた場合にも先の原因で説明したように全く同じことが言える。
プールされたコネクションは特に読み取り専用のコネクションであれば、一回使用した後もコネクションはクローズされずに何度も使いまわされる。
そして通信がしばらく行われなかった場合、プールされていたコネクションはサーバ側のタイムアウト設定により、使えなくなってしまうのである。

コネクションプールの設定にもよるが、プールされていたコネクションはサーバ側でコネクションが破棄されていたとしてもずっとプールされ続けることがある(というか特に設定しないかぎりは通常だとそうなる)
そのため同様にしばらく(サーバのタイムアウト設定以上)に通信が行われなかった後、再び実行しようとすると同じエラーを引き起こす。

対応

対応としてはいくつかあるが、適切なものとしては通信を行う前にコネクションの検証を行うsqlを発行することで回避できる。
scalikejdbcのような内部でDBCPを利用しているようなコネクションプールであれば、公式にサポートされている機能がある。

設定パラメータに存在するvalidationQueryという項目に適当なsqlを設定する。
例えばselect 1 as oneなど。
そうすることでコネクションを利用する前にその検証クエリを毎回発行するようになり、コネクションが切れていた場合は自動的に再接続を行なってくれるようになる。
コネクションプールを利用していない場合については、自身で実装を工夫する必要がある。

検証

ここまでの話を実装レベルで検証してみよう。

mysqlのタイムアウト値

mysqlの実装におけるコネクションのタイムアウト値はwait_timeoutという項目により設定される。
その項目を確認してみよう

show variables like 'wait_timeout';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| wait_timeout  | 28800 |
+---------------+-------+
1 row in set (0.00 sec)

デフォルトでは28800秒である。これは8時間に値する。
すなわちよくあるケースではアプリケーションが最後にデータベースと通信をおこない、その8時間以上経過してから再度データベースと通信を行うような処理を実行しようとしたところでエラーが発生する、というケースである。

検証する上で流石に8時間も待てないので、この時間を変更する

/etc/my.cnfを編集してタイムアウト時間を更新する
今回は下記のように設定することで10秒に指定した

wait_timeout=10

アプリケーションでエラーが発生することの確認

さて、ここでscalikejdbcを用いたplay scalaアプリケーションにて同エラーが発生することを確認する。
テスト用に作成したアプリケーションを用いることとする。
同じ状況が再現できれば、別にアプリケーションはなんでもよい。

application.conf

コネクションプールを利用するためdefaultという接続子を用いて下記のような設定を行う。

db {
  default.driver=com.mysql.jdbc.Driver
  default.url="jdbc:mysql://localhost/test"
  default.username=user
  default.password=password

  default.poolInitialSize = 10
  default.poolMaxSize = 10
}

アプリケーション

検証のため適当なコントローラに下記のような記述をする。
純粋にループしながらselectを行う。ループ中では15秒のwaitを入れる。

def index = Action {
  scalikejdbc.config.DBs.setupAll()

  var name: Option[String] = None

  (0 to 10).foreach(_ => {
    println("try read")
    name = DB readOnly { implicit session =>
      sql"select name from t order by id desc limit 1".map(rs => rs.string("name")).single().apply()
    }
    println(name)
    Thread.sleep(15000)
  })

  Ok("ok")
}

このアプリケーションを実行すると先のエラーが発生した。
予測はあっているようである。

さらに対応としてvalidationQueryを設定してみる。
scalikejdbcにおけるvalidationQueryの設定は下記のようになる。

db {
  default.driver=com.mysql.jdbc.Driver
  default.url="jdbc:mysql://localhost/test"
  default.username=user
  default.password=password

  default.poolValidationQuery="select 1 as one"
  default.poolInitialSize = 10
  default.poolMaxSize = 10
}

この設定を用いてアプリケーションを実行してみると、今度は無事にエラーが発生しないで実行できる。

またこの際のquery.logを確認してみる

...
2016-05-15T23:36:57.488754Z   71 Query	select 1 as one
2016-05-15T23:36:57.489167Z   71 Query	set session transaction read only
2016-05-15T23:36:57.489512Z   71 Query	SET autocommit=1
2016-05-15T23:36:57.490026Z   71 Query	select name from t order by id desc limit 1
...

目的のsqlの直前にvalidationQueryが存在していることが確認できる。
これによって無事に対応することができた。


mac osx におけるファイルディスクリプタの上限

概要

mac osxでmysql5.7.11を用いてアプリケーション開発を行ったところ、特定の動作をした時点でアプリケーションが動作しなくなる現象に直面した。

mysqlのエラーログを確認してみると下記のようなエラーが出ていることが確認できた。

[Warning] File Descriptor 2032 exceedeed FD_SETSIZE=1024

開発にともなって行った「特定の動作」とはmysqlにおいて、あるテーブルにpartitioningを適用したことである。それも結構な数の。
なるほどmysqlエラーログと合わせてみてみるとその状況は察することができる。
partitioningを切ったことで、物理的に異なるファイルとしてその実態データファイル(InnoDBでいうところのibdファイル)が分離された。
mysql上でそれら実体ファイルをオープンしているfile descriptorがosの上限を上回ったのであろう。

この点について原因の調査と、対応方法をまとめる。

検証

さて、ここでアプリケーション上で起こった問題を再現して、再度その問題が憶測と合っているか検証してみよう。

ここで、sqlを作成する簡単なphpプログラムを用意する。
余談だがやっぱ私の年代となるとスクリプトももっぱらphpだな。

テーブルを作成するsqlを生成するphpコード

下記のコードを実行することで、3000個のパーティショニングを日付で切ったテーブルを作成する
ちなみに、paritioningの最後のところでカンマが一つ多くなるので注意されたし。
そのまま実行する場合は構文エラーになるので手動で削除してください。

<?php
date_default_timezone_set('Asia/Tokyo');

$pivot = strtotime('2010-01-01 00:00:00');
create_partition($pivot);

// create partition ddl
function create_partition($date){
	echo "CREATE TABLE t (id BIGINT auto_increment, name VARCHAR(50), purchased DATE, primary key(id, purchased)) ENGINE=InnoDB DEFAULT charset=utf8 PARTITION BY RANGE COLUMNS(purchased) (";
	for($i=0; $i<3000; $i++) {
		echo "PARTITION p{$i} VALUES LESS THAN ('" . date('Y-m-d', $date) . "')," . PHP_EOL;
		$date = strtotime(date('Y-m-d H:i:s', $date) . " +1 days");
	}
	echo ");";
}

データを挿入するsqlを生成するphpコード

続いて各パーティションにデータを挿入してみる。
下記のコードを実行する。

<?php
date_default_timezone_set('Asia/Tokyo');

$pivot = strtotime('2010-01-01 00:00:00');
create_data($pivot);

// insert data
function create_data($date){
	for($i=0; $i<2999; $i++) {
		echo "INSERT INTO t(name, purchased) VALUES('name{$i}', '" . date('Y-m-d H:i:s', $date) . "');" . PHP_EOL;
		$date = strtotime(date('Y-m-d H:i:s', $date) . " +1 days");
	}
}

そしてその状態で再度mysqlへ接続し、use文を用いてデータベースを選択すると

[Warning] File Descriptor 2032 exceedeed FD_SETSIZE=1024

再現した。

調査

原因は概ね特定できたので、この件について対応方法がないかweb上で検索する。

するとピタリ。こちらのmysqlのバグレポートに全く同じ事象が報告されている。

詳しくは上記のリンクに目を通していただけるとよい。
要約すると osx 固有のバグであり、予想していたように FD_SETSIZE が os の規定値を上回っているためである。
また、するとこの os が持っているファイルディスクリプタの上限値を変更できないのか?
ということを想像するが、残念ながらこれは mac osx で動作している現在の mysql5.7.11 では不可能である。

というのもこちらの github コードを参照してもらうとわかるように osx では FD_SETSIZE 決め打ちで上限を規定している。
これを回避するためには自分でソースコードを改修し、リビルドするしかない。

対応

では、この問題に対応できないのか?というと、そういうわけでもない。
別のアプローチで対処する事が可能である。

問題は mysql がテーブルを参照する際にオープンしている file descriptor の数が多すぎることである。
mysql アプリケーションのパラメータを変更することである程度コントロールすることができる。
具体的には一番大きな影響を与えている、テーブルのキャッシュを数を減らすことである

テーブルエントリのキャッシュ数を変更するには下記の項目を my.cnf に付け加える
数値は上限(osxでは1024)に達しないように調整する。

table_open_cache=400

すると一度オープンしたテーブルの file descriptor を保持しないようになるため、問題を解決できる。
なお、この対応方法はパフォーマンスに大きく影響をあたえる場合もあるので十分注意するべきである。
通常の linux ベースのサーバなどでは file descriptor の上限を上げるなどの対応を合わせて検討するべきである。