Open in app

Sign in

Write

Sign in

HikariCPを利用したコネクションプールの出力ログを確認してみる

はじめに

Shinya Morikawa
nextbeat-engineering
25 min readJul 21, 2023

--

こんにちは、”保育園・幼稚園の『タイヘン』を『カンタン』に”をテーマに保育士バンク！コネクトでエンジニアを担当している森川です。

先日、コネクションプールのログを出力して、コネクションがどのような動きをするのかを確認する機会がありました。

その時の復習も兼ねて、この記事ではコネクションプールの出力ログの確認方法について記載したいと思います。

HikariCPについて

弊社で利用している社内フレームワークのIxiaSではDBレイヤーにslickを採用しており、slickでのデフォルトのコネクションプールとしてHikariCPを使用しています。

HikariCPはJavaアプリケーションで利用される高性能で軽量なコネクションプールライブラリです。Spring BootやPlay FrameworkなどとJVM系のWebフレームワークと組み合わせて使用されることが多いです。

Hikari(光)の名前が示す通りに、Githubでも他ライブラリと比べて高速性を打ち出したグラフが掲載されています。

参考) https://github.com/brettwooldridge/HikariCP

またHikariCPでは、コネクションプールの様々な設定値（maxLifetime、maximumPoolSizeなど）や接続前の検証SQL（connectionTestQuery）などを柔軟にカスタマイズすることができます。

よく使用される設定や利用方法については、GitHubに詳細が掲載されています。

GitHub - brettwooldridge/HikariCP: 光 HikariCP・A solid, high-performance, JDBC connection pool at…

光 HikariCP・A solid, high-performance, JDBC connection pool at last. - GitHub - brettwooldridge/HikariCP: 光 HikariCP・A…

github.com

HikariCPの導入方法

今回、Play Frameworkでのサンプルコードで確認していたため、play-slickを使用しました。また、DBはMySQL5.7を利用しています。

build.sbtにplay-slickとMySQLのDBドライバの依存関係を追加します。

  • build.sbt
libraryDependencies ++= Seq(
  "com.typesafe.play" %% "play-slick" % "5.0.0",
  "mysql" % "mysql-connector-java" % "5.1.39",
)

純正slickを利用する場合は以下の依存関係をbuild.sbtに追記します。

libraryDependencies ++= Seq(
  "com.typesafe.slick" %% "slick" % "3.3.3", 
  "com.typesafe.slick" %% "slick-hikaricp" % "3.3.3",
  "mysql" % "mysql-connector-java" % "5.1.39",
)

DBに関する設定はapplication.confに記載します。コネクションプールに関する設定は記述しておらず、基本的なDB接続に関する設定のみ記載しています。

  • application.conf
slick.dbs {
  default {
      profile = "slick.jdbc.MySQLProfile$"
      db {
        driver = "com.mysql.jdbc.Driver"
        jdbcUrl = "jdbc:mysql://localhost:3306/[your_db_name]"
        user = "[your_username]"
        password = "[your_password]"
      }
  }
}

HikariCPのログデータの出力設定

HikariCPのデバッグログの出力設定をlogbackに追記します。デバッグログは量が多いため、ログファイルに出力するようにしました。

  • logback.xml
<configuration>
  
  <!--出力ファイルとエンコード設定-->
  <appender name="FILE" class="ch.qos.logback.core.FileAppender">
    <file>logs/hikaricp.log</file>
    <encoder>
      <pattern>%date %level [%thread] %logger{10} [%file:%line] %msg%n</pattern>
    </encoder>
  </appender>

  <!--HikariCPのログ出力設定-->
  <logger name="com.zaxxer.hikari" level="DEBUG" additivity="false">
    <appender-ref ref="FILE" />
  </logger>

</configuration>

HikariCPのログデータの内容について

上記ログ設定を追加してDB接続処理を実行します。

リクエストについては負荷測定ツールのGatlingを利用して、同時に複数リクエストが実行されるような処理を投げています。

DB接続処理が実行されると、ログファイルに以下コネクションプールに関する設定ログが出力されます。

c.z.h.HikariConfig [HikariConfig.java:1020] slick.dbs.default.db - configuration:
c.z.h.HikariConfig [HikariConfig.java:1052] allowPoolSuspension.............false
c.z.h.HikariConfig [HikariConfig.java:1052] autoCommit......................true
c.z.h.HikariConfig [HikariConfig.java:1052] catalog.........................none
c.z.h.HikariConfig [HikariConfig.java:1052] connectionInitSql...............none
c.z.h.HikariConfig [HikariConfig.java:1052] connectionTestQuery.............none
c.z.h.HikariConfig [HikariConfig.java:1052] connectionTimeout...............30000
c.z.h.HikariConfig [HikariConfig.java:1052] dataSource......................none
c.z.h.HikariConfig [HikariConfig.java:1052] dataSourceClassName.............none
c.z.h.HikariConfig [HikariConfig.java:1052] dataSourceJNDI..................none
c.z.h.HikariConfig [HikariConfig.java:1052] dataSourceProperties............{password=<masked>}
c.z.h.HikariConfig [HikariConfig.java:1052] driverClassName................."com.mysql.jdbc.Driver"
c.z.h.HikariConfig [HikariConfig.java:1052] healthCheckProperties...........{}
c.z.h.HikariConfig [HikariConfig.java:1052] healthCheckRegistry.............none
c.z.h.HikariConfig [HikariConfig.java:1052] idleTimeout.....................600000
c.z.h.HikariConfig [HikariConfig.java:1052] initializationFailTimeout.......-1
c.z.h.HikariConfig [HikariConfig.java:1052] isolateInternalQueries..........false
c.z.h.HikariConfig [HikariConfig.java:1052] jdbcUrl.........................jdbc:mysql://localhost:3306/sample
c.z.h.HikariConfig [HikariConfig.java:1052] leakDetectionThreshold..........0
c.z.h.HikariConfig [HikariConfig.java:1052] maxLifetime.....................1800000
c.z.h.HikariConfig [HikariConfig.java:1052] maximumPoolSize.................20
c.z.h.HikariConfig [HikariConfig.java:1052] metricRegistry..................none
c.z.h.HikariConfig [HikariConfig.java:1052] metricsTrackerFactory...........none
c.z.h.HikariConfig [HikariConfig.java:1052] minimumIdle.....................20
c.z.h.HikariConfig [HikariConfig.java:1052] password........................<masked>
c.z.h.HikariConfig [HikariConfig.java:1052] poolName........................"slick.dbs.default.db"
c.z.h.HikariConfig [HikariConfig.java:1052] readOnly........................false
c.z.h.HikariConfig [HikariConfig.java:1052] registerMbeans..................false
c.z.h.HikariConfig [HikariConfig.java:1052] scheduledExecutor...............none
c.z.h.HikariConfig [HikariConfig.java:1052] schema..........................none
c.z.h.HikariConfig [HikariConfig.java:1052] threadFactory...................internal
c.z.h.HikariConfig [HikariConfig.java:1052] transactionIsolation............default
c.z.h.HikariConfig [HikariConfig.java:1052] username........................"username"
c.z.h.HikariConfig [HikariConfig.java:1052] validationTimeout...............5000

手動設定を行っていないため、デフォルトの設定値が出力されています。

多くの設定項目がありますが、いくつか代表的なものについて見てみます。

  1. connectionTimeout:
    接続要求がこの時間を超えて待機すると、タイムアウト例外がスローされる時間です。値を短くすることで、接続不可の検知を迅速に行うことができますがタイムアウトエラーの可能性が高くなります。一方で値を長くするとタイムアウトの可能性を減らせる一方でアプリケーションの応答時間が増加するおそれがあります。デフォルトは30000ミリ秒（30秒）で設定されています。
  2. maxLifetime:
    コネクションプール接続が生存する最大時間です。接続時間がこの時間を超えると、接続は再利用される前に閉じられ、新しい接続が代わりに開かれます。これにより、データベースサーバー上での不必要な接続の持続時間が制限されます。ただし、値が短すぎると、接続が頻繁に作り直され、その結果パフォーマンスが低下する可能性があります。デフォルトは1800000ミリ秒（30分）です。
  3. connectionTestQuery：
    接続が有効かどうかを確認するためのSQLを指定することができます。この設定で指定されたクエリを使って、接続をプールから取り出す前に接続がまだ有効かどうかをチェックすることができます。

その他多くの設定がありますが、詳細はGithubのREADMEをご参照ください。

これらの設定が接続開始時にログ出力されることで、プール設定について確認することができます。

また上記プール設定表示後は、以下ログが出力されます。

c.z.h.p.HikariPool [HikariPool.java:709] db - Added connection com.mysql.jdbc.JDBC4Connection@49e11175
c.z.h.p.HikariPool [HikariPool.java:709] db - Added connection com.mysql.jdbc.JDBC4Connection@1c79c601
c.z.h.p.HikariPool [HikariPool.java:709] db - Added connection com.mysql.jdbc.JDBC4Connection@19de77df
c.z.h.p.HikariPool [HikariPool.java:709] db - Added connection com.mysql.jdbc.JDBC4Connection@190c3ecd
c.z.h.p.HikariPool [HikariPool.java:709] db - Added connection com.mysql.jdbc.JDBC4Connection@57c87e60
c.z.h.p.HikariPool [HikariPool.java:709] db - Added connection com.mysql.jdbc.JDBC4Connection@15dda4e4
c.z.h.p.HikariPool [HikariPool.java:709] db - Added connection com.mysql.jdbc.JDBC4Connection@30dc5623
c.z.h.p.HikariPool [HikariPool.java:709] db - Added connection com.mysql.jdbc.JDBC4Connection@6cd16bd8
c.z.h.p.HikariPool [HikariPool.java:709] db - Added connection com.mysql.jdbc.JDBC4Connection@3d66b252
c.z.h.p.HikariPool [HikariPool.java:709] db - Added connection com.mysql.jdbc.JDBC4Connection@7e6ecb28
c.z.h.p.HikariPool [HikariPool.java:709] db - Added connection com.mysql.jdbc.JDBC4Connection@23ebbef1
c.z.h.p.HikariPool [HikariPool.java:709] db - Added connection com.mysql.jdbc.JDBC4Connection@7a99164d
c.z.h.p.HikariPool [HikariPool.java:709] db - Added connection com.mysql.jdbc.JDBC4Connection@5b21354d
c.z.h.p.HikariPool [HikariPool.java:709] db - Added connection com.mysql.jdbc.JDBC4Connection@926d8b9
c.z.h.p.HikariPool [HikariPool.java:709] db - Added connection com.mysql.jdbc.JDBC4Connection@418c9f8a
c.z.h.p.HikariPool [HikariPool.java:709] db - Added connection com.mysql.jdbc.JDBC4Connection@5add8904
c.z.h.p.HikariPool [HikariPool.java:709] db - Added connection com.mysql.jdbc.JDBC4Connection@7afa616
c.z.h.p.HikariPool [HikariPool.java:709] db - Added connection com.mysql.jdbc.JDBC4Connection@4952d504
c.z.h.p.HikariPool [HikariPool.java:709] db - Added connection com.mysql.jdbc.JDBC4Connection@111c4fc8
c.z.h.p.HikariPool [HikariPool.java:709] db - Added connection com.mysql.jdbc.JDBC4Connection@4bf2d58f

“Added connection”が示す通り、これはHikariCPが新しいコネクションをコネクションプールに追加したことを表示しています。

上記では20個のコネクションが追加されています。これは先程のプール設定のうち、`maximumPoolSize`のデフォルト設定値である`20`の値が反映されているためです。

さらにこの後しばらくログ眺めていると、30秒ごとに定期的にコネクションプールの状態に関するログが出力されます。

[db housekeeper] c.z.h.p.HikariPool [HikariPool.java:411] db - Pool stats (total=20, active=20, idle=0, waiting=0)
[db housekeeper] c.z.h.p.HikariPool [HikariPool.java:411] db - Pool stats (total=20, active=0, idle=20, waiting=0)
[db housekeeper] c.z.h.p.HikariPool [HikariPool.java:411] db - Pool stats (total=20, active=0, idle=20, waiting=0)
…
…

Pool statsの内容について確認していきます。

  • Pool stats (total=20, active=0, idle=20, waiting=0)

このログは、HikariCPによるコネクションプールの状態を示しています。それぞれの出力値について解説します。

  • total: プールが現在管理している全接続数を示します。これはアクティブな接続とアイドル状態の接続を含んだ合計値です。
  • active: 現在アクティブで、何らかのクエリを処理中の接続数を示します。上記の例ではアクティブな接続は0個で、すなわち現時点でデータベースと通信している接続はありません。
  • idle: 現在アイドル状態で、クエリ処理に使われていない接続数を示します。上記の例では、すべての接続（20接続）がアイドル状態で、新しいクエリが来たときにすぐに使用できる状態です。
  • waiting: 新しいデータベース接続を待っているスレッドの数を示します。このログでは待機中のスレッドはいません。

これらの出力状況を確認することで、コネクションプールがどのような利用状況になっているのかを確認することができます。

（参考）

  • [db housekeeper]

housekeeperはこのログの出力スレッド名です。このhousekeeperスレッドが、接続プールの状態を定期的にチェックし、アイドル接続の削除や生存確認などのメンテナンスタスクを実行しています。

HikariCPの“housekeeper”スレッドは通常、30秒ごとに実行されるため、上記のPool statsに関するログも30秒間隔で出力されます。

この値を変更する際には実行時オプションで、`Dcom.zaxxer.hikari.housekeeping.periodMs`
でミリ秒単位で出力間隔を設定することができます。

例えば、以下コマンドで、アプリケーションを起動すると10秒間隔でメンテナンスログを出力することができます。

sbt run -Dcom.zaxxer.hikari.housekeeping.periodMs=10000

maxLifetimeを変更する

次にいくつかのコネクションプール設定を変更することで、どのようなログが出力されるのかを見ていきたいと思います。

まずはコネクションプール接続が生存する最大時間を設定しているmaxLifetimeを変更してみます。

デフォルトでは1800000ミリ秒（30分）ですが、これを30000ミリ秒（30秒）に設定した場合を確認してみます。

コネクションプールの設定を変更するには、application.confにコネクションプールに関する設定を追記します。

slick.dbs {
  default {
      profile = "slick.jdbc.MySQLProfile$"
      db {
        // その他設定

        maxLifetime = 30000 // maxLifetimeを30000に設定
      }
  }
}

上記の設定を追加して、再度DB接続処理を実行します。

接続開始時のプール設定で、maxLifetimeが手動設定した値に変更されていることが確認できます。

 c.z.h.HikariConfig [HikariConfig.java:1052] maxLifetime.....................30000

そしてDB接続を開始してから30秒経過後、以下のようなデバッグログが出力されました。

[db connection closer] c.z.h.p.PoolBase [PoolBase.java:129] db - Closing connection com.mysql.jdbc.JDBC4Connection@58934279: (connection has passed maxLifetime)
[db connection adder] c.z.h.p.HikariPool [HikariPool.java:709] db - Added connection com.mysql.jdbc.JDBC4Connection@214268f1
[db connection closer] c.z.h.p.PoolBase [PoolBase.java:129] db - Closing connection com.mysql.jdbc.JDBC4Connection@636a01d6: (connection has passed maxLifetime)
[db connection adder] c.z.h.p.HikariPool [HikariPool.java:709] db - Added connection com.mysql.jdbc.JDBC4Connection@6fd4ad9

“(connection has passed maxLifetime)”と出力されている通り、maxLifetimeを超過したことによりコネクションのクローズ処理が動いていることがわかります。

また、その後にコネクションプールサイズを戻すためにコネクションが再度追加されています。

上記から手動設定したプール設定によりmaxLifetimeの値が変更されたことが確認できました。

（補足）

はじめmaxLifeTimeの値を10000ミリ秒（10秒）で設定しようとしたのですがapplication.confに設定しても、うまく反映されずデフォルトの30分のままとなっていました。

そこでHikariCPのログを確認したところ以下Warningログが出力されていました。

db - maxLifetime is less than 30000ms, setting to default 1800000ms.

最小値は30秒までしか設定できないため、デフォルトの30分に自動で設定されていることが原因でした。

The minimum allowed value is 30000ms (30 seconds). Default: 1800000 (30 minutes)

その後Githubを確認すると、maxLifetimeの説明に下限に関する記載がありました。。

connectionTestQueryを設定する

もう一つconnectionTestQueryの設定値を変更して、疎通クエリで失敗した時にどのようなエラーログが出力されるのかも見てみたいと思います。

先程のmaxLifetimeと同様にapplication.confに設定を追記します。
今回はあえて疎通に失敗するような、存在しないテーブルからの取得処理をテストクエリに設定してみます。

  • application.conf
slick.dbs {
  default {
      profile = "slick.jdbc.MySQLProfile$"
      db {
        // その他設定
        connectionTestQuery = "SELECT * FROM unknown_table" //存在しないテーブルからの取得処理を設定
      }
  }
}

上記設定後、再起動するとプール設定に、設定値が追加されていることが確認できます。

c.z.h.HikariConfig [HikariConfig.java:1052] connectionTestQuery............."SELECT * FROM unknown_table"

その後のログ出力を確認すると、テストクエリで失敗したことによるエラーログが発生していることが確認できました。

ERROR [db connection adder] c.z.h.p.PoolBase [PoolBase.java:461] db - Failed to execute connection test query (Table 'sample.unknown_table' doesn't exist).
DEBUG [db connection adder] c.z.h.p.PoolBase [PoolBase.java:129] db - Closing connection com.mysql.jdbc.JDBC4Connection@583b5c97: (Failed to create/setup connection)
DEBUG [db connection adder] c.z.h.p.HikariPool [HikariPool.java:487] db - Cannot acquire connection from data source
com.mysql.jdbc.exceptions.jdbc4.MySQLSyntaxErrorException: Table 'sample.unknown_table' doesn't exist

テストクエリが失敗した場合には、失敗した接続はコネクションプールから削除されます。その後、新しい接続が作成されてプールに追加されることになります。

この機能を用いて、コネクション接続前の疎通確認を柔軟に設定することができます。

まとめ

コネクションプールのログ出力に関する設定と、出力されるログ内容、設定値を変更した際のログ出力の変化について確認しました。

実験のため極端な値やあえて失敗するテストクエリを記載しての確認のみでしたが、調査する中で、最適なパフォーマンスを得るための調整は重要であると同時に様々な条件を考慮する必要があることがわかりました。

今回は一部設定値の調整結果を見ることしかできなかったのですが、テスト環境を用いてその他の設定値についても検証を進めてみたいと思っています。

We are hiring!

本記事をご覧いただき、ネクストビートの技術や組織についてもっと話を聞いてみたいと思われた方、カジュアルにお話しませんか？

・今後のキャリアについて悩んでいる
・記事だけでなく、より詳しい内容について知りたい
・実際に働いている人の声を聴いてみたい

など、まだ転職を決められていない方でも、ネクストビートに少しでもご興味をお持ちいただけましたら、ぜひカジュアルにお話しましょう！

🔽申し込みはこちら
https://hrmos.co/pages/nextbeat/jobs/1000008

また、ネクストビートについてはこちらもご覧ください。

🔽エントランスブック
https://note.nextbeat.co.jp/n/nd6f64ba9b8dc

Engineer
Hikaricp
Play Framework

--

--

Shinya Morikawa
nextbeat-engineering

Written by Shinya Morikawa

0 Followers
Writer for

Help

Status

About

Careers

Press

Blog

Privacy

Terms

Text to speech

Teams