※KDDIコマースフォワード㈱ 、略称「KCF」は2019年4月1日、同グループ会社の㈱ルクサと合併し「auコマース＆ライフ株式会社」として再設立いたしました。 本記事は2019年3月31日以前に書かれた記事のアーカイブとなります。予めご了承ください。
初めまして。KDDIコマースフォワードでエンジニアをしております T.T. です。
みなさん、プロジェクトに参加したらまず何をされますか？既に動くシステムがあれば一通りさわってみて、フォームにスクリプトを混入してみたり、通信中にWi-Fiを切ってみたりしますよね？
今回、とあるシステムで MySQL の実行中プロセスを全部殺したらエラーを吐き続けて２度と復旧しなくなるという現象に遭遇しました。この現象、勘の良い方ならすぐにDBコネクション周りの問題だろうと気づくでしょう。答えを先に言うとコネクション・プーリングの取り扱い不備による不具合でした。
知っている人にとってはなんて事ないミスで解決も一瞬かと思いますが、原因の調査と解決までの過程を残しておくことで、これからプログラミングを学ぶ人へのコードリーディングのサンプルになるかなと思い今回話させていただきます。
ちなみに筆者のスキルですが、Javaを書いていたのは10年以上前（かろうじてJava5を触ったくらい）。Spring 等の Java 界隈の FW や ORM は使ったことがないお粗末なスキルです。以上予防線でした。
Connection Pooling
コネクション・プーリング（以降 CP）とは、データベースとの接続を予め一定数確立しておいてそれを使いまわす手法のことです。一度確立したコネクションを2回目以降も再利用することで、接続要求に発生するコストを削減することが期待されます。
メジャーなWebフレームワークには大抵組み込みでCPの機能が提供されているか、デフォルトで当該機能を提供するライブラリがバンドルされていると思いますので、この機能を使ってWebアプリケーションを実装した経験をお持ちの方は多いと思います。
その一方で、大変便利な機能ではありますが提供しているサービスの規模や内容によっては都度接続でも問題にならないと判断するケースもあり、CPを使わなかったり意識したことがない方もいらっしゃるかもしれません。かくいう私も今まで比較的大規模なサービスでもCPを使わず都度接続で処理を行っていたため、あまりこの機能に触れる機会がありませんでした。
環境情報
- Spring Boot: 2.0.1.RELEASE
- Kotlin
- DB: MySQL
- JDBC connection pool: HikariCP 2.7.8
- JDBCドライバ: mysql-connecter-java 6.0.6
- ORM: JOOQ 3.10.4
詳しくはこちらの記事にありますので、興味がある方はぜひご一読ください。
現象の確認
Spring Boot を起動しシステムの正常動作を確認。その後 MySQL のプロセスを全部 kill して動作確認をすると以下のエラーが出続けていました。
WARN com.zaxxer.hikari.pool.ProxyConnection HikariPool-2 - Connection com.mysql.cj.jdbc.ConnectionImpl@2faa43cc marked as broken because of SQLSTATE(08S01), ErrorCode(0) com.mysql.cj.jdbc.exceptions.CommunicationsException: Communications link failure Caused by: com.mysql.cj.core.exceptions.CJCommunicationsException: Communications link failure
本システムではCPを使用していることを事前に聞いていたので、プロセスが全て死んだとしてもCPの機能で再接続してコネクションをプールし直し、その中からコネクションを使用することですぐに復旧すると思っていました。しかしエラーの文言からはDBとの疎通で失敗している様子です。コネクションの再作成が動いてないのでしょうか？
おかしいなと思い、このエラーが出ているときの MySQL プロセスを確認すると予想に反してしっかりと新しいプロセスができていました。
mysql> show full processlist; +-----+-------+-----------------+---------+---------+------+----------+-----------------------+ | Id | User | Host | db | Command | Time | State | Info | +-----+-------+-----------------+---------+---------+------+----------+-----------------------+ | 206 | fizz | localhost | NULL | Query | 0 | starting | show full processlist | | 217 | fizz | localhost:48442 | buzz | Sleep | 3 | | NULL | | 218 | fizz | localhost:48444 | buzz | Sleep | 3 | | NULL | | 219 | fizz | localhost:48446 | buzz | Sleep | 3 | | NULL | | 220 | fizz | localhost:48448 | buzz | Sleep | 3 | | NULL | | 221 | fizz | localhost:48450 | buzz | Sleep | 2 | | NULL | | 222 | fizz | localhost:48452 | buzz | Sleep | 2 | | NULL | | 223 | fizz | localhost:48454 | buzz | Sleep | 2 | | NULL | | 224 | fizz | localhost:48456 | buzz | Sleep | 2 | | NULL | | 225 | fizz | localhost:48458 | buzz | Sleep | 2 | | NULL | | 226 | fizz | localhost:48460 | buzz | Sleep | 2 | | NULL | +-----+-------+-----------------+---------+---------+------+----------+-----------------------+
プロセスが10個います。本システムで使用している Connection Pool 実装は HikariCP。デフォルトの最大プール数は10なのでこれが効いていると思われます。
調査開始
現象が確認できたので調査を開始。まずは本システムで DataSource の設定をしているコードを見てみました。
@Configuration class DataBaseConfigure { @Configuration @ConfigurationProperties(prefix = PROPERTY_PREFIX) class DataSourceConfigure { var url = "" var username = "" var password = "" var driverClassName = "" @Bean(DATA_SOURCE_NAME) fun dataSource(): DataSource { return DataSourceBuilder.create() .driverClassName(driverClassName) .url(url) .username(username) .password(password) .build() } } }
CPのサイズ諸々は特に指定していないみたいです。諸々調整したいので HikariCP の Config から HikariDataSource を作成して色々設定できるようにします。
@Configuration class DataBaseConfigure { @Configuration @ConfigurationProperties(prefix = PROPERTY_PREFIX) class DataSourceConfigure { var url = "" var username = "" var password = "" var driverClassName = "" var connectionTimeout: Long = TimeUnit.SECONDS.toMillis(30) var minimumIdle = 5 var maximumPoolSize = 5 var idleTimeout: Long = TimeUnit.MINUTES.toMillis(10) var maxLifetime: Long = TimeUnit.MINUTES.toMillis(30) var connectionInitSql = "SELECT 1" @Bean(DATA_SOURCE_NAME) fun dataSource(): DataSource { val config = HikariConfig() config.driverClassName = driverClassName config.jdbcUrl = url config.username = username config.password = password config.minimumIdle = minimumIdle config.maximumPoolSize = maximumPoolSize config.idleTimeout = idleTimeout config.maxLifetime = maxLifetime config.connectionInitSql = connectionInitSql config.connectionTimeout = connectionTimeout return HikariDataSource(config) } } }
Spring を再起動して MySQL プロセスを確認。プロセスが5個になっているので期待通り設定を読んでるみたいです。
mysql> show full processlist; +-----+-------+-----------------+---------+---------+------+----------+-----------------------+ | Id | User | Host | db | Command | Time | State | Info | +-----+-------+-----------------+---------+---------+------+----------+-----------------------+ | 206 | fizz | localhost | NULL | Query | 0 | starting | show full processlist | | 248 | fizz | localhost:48534 | buzz | Sleep | 1 | | NULL | | 249 | fizz | localhost:48536 | buzz | Sleep | 1 | | NULL | | 250 | fizz | localhost:48538 | buzz | Sleep | 1 | | NULL | | 251 | fizz | localhost:48540 | buzz | Sleep | 1 | | NULL | | 252 | fizz | localhost:48542 | buzz | Sleep | 1 | | NULL | +-----+-------+-----------------+---------+---------+------+----------+-----------------------+
画面にアクセス。正常に表示されていることを確認して再度プロセスを全部殺します。
mysql> kill 248;
プロセスが全部死んだのを確認。
mysql> show full processlist; +-----+-------+-----------------+---------+---------+------+----------+-----------------------+ | Id | User | Host | db | Command | Time | State | Info | +-----+-------+-----------------+---------+---------+------+----------+-----------------------+ | 206 | fizz | localhost | NULL | Query | 0 | starting | show full processlist | +-----+-------+-----------------+---------+---------+------+----------+-----------------------+
もう一度画面にアクセスしてみると、やはりエラーでています。
WARN com.zaxxer.hikari.pool.ProxyConnection HikariPool-2 - Connection com.mysql.cj.jdbc.ConnectionImpl@2faa43cc marked as broken because of SQLSTATE(08S01), ErrorCode(0) com.mysql.cj.jdbc.exceptions.CommunicationsException: Communications link failure Caused by: com.mysql.cj.core.exceptions.CJCommunicationsException: Communications link failure
でも mysql のプロセスを見たらプロセスは5個あります。
mysql> show full processlist; +-----+-------+-----------------+---------+---------+------+----------+-----------------------+ | Id | User | Host | db | Command | Time | State | Info | +-----+-------+-----------------+---------+---------+------+----------+-----------------------+ | 206 | fizz | localhost | NULL | Query | 0 | starting | show full processlist | | 253 | fizz | localhost:48554 | buzz | Sleep | 467 | | NULL | | 254 | fizz | localhost:48556 | buzz | Sleep | 467 | | NULL | | 255 | fizz | localhost:48558 | buzz | Sleep | 467 | | NULL | | 256 | fizz | localhost:48560 | buzz | Sleep | 467 | | NULL | | 257 | fizz | localhost:48564 | buzz | Sleep | 467 | | NULL | +-----+-------+-----------------+---------+---------+------+----------+-----------------------+
ここまでで、CPは期待通りに設定値を見てコネクションを作成＆プールし、コネクションが切断されても再作成＆プールしていることがわかりました。そこからCPを利用する側がクローズしたコネクションを参照し続けているのだろうと推測できます。というわけで、以降はコネクションを利用する側のコードを読んでいきます。
コード・リーディング
コネクションを利用しているのは ORM の JOOQ です。本システムで JOOQ がコネクションを取得していそうな箇所を探します。JOOQでは org.jooq.DSLContext というのがクエリ実行の基点となるようです。
Apart from the DSL, this contextual DSL is the main entry point for client code, to access jOOQ classes and functionality that are related to Query execution.
該当してそうなコードがあったのでそこを基点に JOOQ のコードを読んでいきます。Javadocのサンプルにあるコードそのままですね。
@Bean(DSL_NAME) fun dslContext(@Qualifier(DATA_SOURCE_NAME) dataSource: DataSource): DSLContext { return DSL.using(dataSource.connection, SQLDialect.MYSQL) }
ただ闇雲に読んでもしょうがないのでキーワードを探します。ログを見るとコネクションをもらっているときに acquire という単語が使われているので、この単語をキーに JOOQ のコードを読んでいきましょう。
DEBUG org.springframework.jdbc.datasource.DataSourceTransactionManager Acquired Connection [HikariProxyConnection@1843070619 wrapping com.mysql.cj.jdbc.ConnectionImpl@1990e95b] for JDBC transaction
コンストラクタを辿っていきます。
public static DSLContext using(Connection connection, SQLDialect dialect) { return new DefaultDSLContext(connection, dialect, null); }
org/jooq/impl/DefaultDSLContext
public DefaultDSLContext(Connection connection, SQLDialect dialect, Settings settings) { this(new DefaultConfiguration(new DefaultConnectionProvider(connection), null, null, null, null, null, null, null, null, null, null, dialect, settings, null)); }
org/jooq/impl/DefaultConnectionProvider
public DefaultConnectionProvider(Connection connection) { this(connection, false); } DefaultConnectionProvider(Connection connection, boolean finalize) { this.connection = connection; this.finalize = finalize; } @Override public final Connection acquire() { return connection; }
acquire 発見。コンストラクタでセットされたコネクションをただ返すだけのメソッドです。ということは、このコンストラクタを使うと最初にセットしたコネクションをずっと参照してしまうんじゃないでしょうか？
どうもCPで管理しているコネクションを使っていない気がします。DataSourceConfigure クラスにて DataSource として HikariDataSource を返すようにしているので、こちら経由でコネクションを返すような実装になっている箇所を探します。
DSL.java を新ためて読むとそれらしいメソッドがあるのでさらに読んでいきます。
public static DSLContext using(DataSource datasource, SQLDialect dialect) { return new DefaultDSLContext(datasource, dialect); }
org/jooq/impl/DefaultDSLContext
public DefaultDSLContext(DataSource datasource, SQLDialect dialect) { this(datasource, dialect, null); } public DefaultDSLContext(DataSource datasource, SQLDialect dialect, Settings settings) { this(new DefaultConfiguration(new DataSourceConnectionProvider(datasource), null, null, null, null, null, null, null, null, null, null, dialect, settings, null)); }
org/jooq/impl/DataSourceConnectionProvider
public DataSourceConnectionProvider(DataSource dataSource) { this.dataSource = dataSource; } @Override public Connection acquire() { try { return dataSource.getConnection(); } catch (SQLException e) { throw new DataAccessException("Error getting connection from data source " + dataSource, e); } }
こちらの acquire ですとデータソース経由でコネクションを取得していそうなので CPで管理するコネクションが返ってきそうです。ここまでくると原因と解決方法に関してははおおよそ検討がつきますので一安心できました。
心に余裕ができると折角なので HikariCP のコードも読んどくかとなりますよね。プールが枯渇していれば作成して、あればその中から返してるっぽいですね。
com/zaxxer/hikari/HikariDataSource
@Override public Connection getConnection() throws SQLException { if (isClosed()) { throw new SQLException("HikariDataSource " + this + " has been closed."); } if (fastPathPool != null) { return fastPathPool.getConnection(); } // See http://en.wikipedia.org/wiki/Double-checked_locking#Usage_in_Java HikariPool result = pool; if (result == null) { synchronized (this) { result = pool; if (result == null) { validate(); LOGGER.info("{} - Starting...", getPoolName()); try { pool = result = new HikariPool(this); this.seal(); } catch (PoolInitializationException pie) { if (pie.getCause() instanceof SQLException) { throw (SQLException) pie.getCause(); } else { throw pie; } } LOGGER.info("{} - Start completed.", getPoolName()); } } } return result.getConnection(); }
com/zaxxer/hikari/pool/HikariPool
public Connection getConnection(final long hardTimeout) throws SQLException { suspendResumeLock.acquire(); final long startTime = currentTime(); try { long timeout = hardTimeout; do { PoolEntry poolEntry = connectionBag.borrow(timeout, MILLISECONDS); if (poolEntry == null) { break; // We timed out... break and throw exception } final long now = currentTime(); if (poolEntry.isMarkedEvicted() || (elapsedMillis(poolEntry.lastAccessed, now) > ALIVE_BYPASS_WINDOW_MS && !isConnectionAlive(poolEntry.connection))) { closeConnection(poolEntry, poolEntry.isMarkedEvicted() ? EVICTED_CONNECTION_MESSAGE : DEAD_CONNECTION_MESSAGE); timeout = hardTimeout - elapsedMillis(startTime); } else { metricsTracker.recordBorrowStats(poolEntry, startTime); return poolEntry.createProxyConnection(leakTaskFactory.schedule(poolEntry), now); } } while (timeout > 0L); metricsTracker.recordBorrowTimeoutStats(startTime); throw createTimeoutException(startTime); } catch (InterruptedException e) { Thread.currentThread().interrupt(); throw new SQLException(poolName + " - Interrupted during connection acquisition", e); } finally { suspendResumeLock.release(); } }
解決
長々とコードを見てきましたが、原因は端的に言ってコネクションの取得先が違っていた、というものでした。というわけで直します。JOOQの DSLContext を返している箇所に戻って1行書き換えます。たったこれだけ！
@Bean(DSL_NAME) fun dslContext(@Qualifier(DATA_SOURCE_NAME) dataSource: DataSource): DSLContext { - return DSL.using(dataSource.connection, SQLDialect.MYSQL) + return DSL.using(dataSource, SQLDialect.MYSQL) }
再度テスト。Spring 起動後、MySQLのプロセスを全部killしてから画面にアクセスすると... connection のチェックをして...
WARN com.zaxxer.hikari.pool.PoolBase HikariPool-2 - Failed to validate connection com.mysql.cj.jdbc.ConnectionImpl@2919cabd (No operations allowed after connection closed.)
その後にコネクション作り直している。
DEBUG org.springframework.jdbc.datasource.DataSourceTransactionManager Acquired Connection [HikariProxyConnection@1381647274 wrapping com.mysql.cj.jdbc.Con
そして問題なく画面表示されました！
最後に
以上でCPのコネクションが使われない不具合の原因と解決は終了です。
冒頭にも書きましたが Java や JOOQ を知っている人にとっては、何てことのないミスで解決も一瞬なんだろうと想像します。しかし知識がない人にとっては手探りで調査し解決を探るしかありません。そんな時に一番身近で手っ取り早く確実な情報源はコードです。初学者にとってはライブラリのコードを読むことに抵抗があるかもしれません。ですがそこを乗り越えてコードを読むことを習慣付けられれば、問題に遭遇した時でも最後はコードを読めば何とかなるだろう、と楽観的に構えられる余裕ができると思います。
偉そうなことを書いていますが、これは自分への戒めでもあります。困ったらググる、も正しいですが、コードを読む習慣も忘れずに日々精進していきたいものです。
