概要
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が存在していることが確認できる。
これによって無事に対応することができた。
コメントを残す