前回の記事でElasticsearchを導入し、検索APIのパフォーマンスを大幅に向上させました。
設定したパフォーマンス目標は平均応答時間 < 200ms、Error Rate < 0.1%でした。ESの導入によってMySQL全文検索の構造的な限界は克服しましたが、VUser 300名の負荷でGET 876ms、POST 1,210msとなり、目標には届いていない状態です。
パフォーマンステスト中にトラフィックが集中する状況でリクエストを1件直接投げてみたときも約1秒かかり、目標の200msには程遠い状態でした。特にPOSTリクエスト（1200ms）は目標の6倍に達していました。
原因を把握するためにGrafanaダッシュボードのさまざまな指標を確認しました。
このとき、いくつか目立つ指標が見えました。JVMのスレッドの状態とHikariCPのコネクションの状態でした。
- timed-waiting状態のスレッド：197個
- HikariCPのコネクションを待っているスレッド：189個
Tomcatスレッドプールの最大サイズのデフォルト値は200個、HikariCPコネクションプールの最大サイズのデフォルト値は10個です。
これらの値をすべてデフォルト値で使用したとき、上記のダッシュボードのような結果が現れました。
まず結論から：デフォルト設定でどんなボトルネックが生じたか？#
この記事の核心は以下の3点です。
- Tomcatの
threads.max=200とHikariCPのmaximum-pool-size=10の組み合わせでは、多くのリクエストスレッドがDBコネクションを待ちながらtimed-waiting状態に縛られました。 - このテスト環境（vCPU 2個、メモリ8GB）では、Tomcat
60、HikariCP40の組み合わせが最も速い応答時間を示しました。 - ただし、スレッド数を極端に減らしたり増やしたりすると、それぞれスループットの低下や外部I/Oの競合増加といった別のボトルネックが現れました。
スレッドたちは実際にどこで待機しているのか？#
ConnectionsのPending値を見ると、おおよそtimed-waiting状態にあるスレッドたちはコネクションプールを取得するために待機していると推定されます。
しかし100%確信することは難しかったです。なぜなら、テスト中のAPIではElasticsearchも使用していたからです。
Elasticsearchクライアントの設定コードを確認すると：
DEFAULT_MAX_CONN_PER_ROUTE：単一ノードに許可される最大同時接続10個DEFAULT_MAX_CONN_TOTAL：すべてのノードに許可される総同時接続30個
上記の値をデフォルトで使用しています。
コネクションを取得するためにPendingしているスレッドは189個なのに、timed-waitingスレッドの数は197個です。8個ほど差があります。そしてwaiting状態にあるスレッドも9個ほどあります。これらのスレッドが何をしているのか把握しにくい状況でした。
そのため、Thread dumpを使って各スレッドの状態をより詳しく確認する必要がありました。
Thread dumpから見ると実際の原因は何か？#
Thread dumpはjcmdコマンドで取得し、分析はfastthread.ioサイトを利用しました。
runnable状態のスレッドは何をしていたのか？#
3つのスレッドダンプを取得して比較してみると、runnable状態のスレッドはほとんどがJVM内部の処理とGCを担当するスレッドで構成されており、実際にコネクションからデータを読んでいるスレッドは2個ほどでした。
MySQLを読んでいるスレッド1個とElasticsearchを読んでいるスレッド1個、またはMySQLを読んでいるスレッド2個とElasticsearchを読んでいるスレッド0個というケースがありました。
waiting状態のスレッドはなぜ発生したのか？#
waitingに該当するスレッドは合計11個で、そのうち8個のスレッドがElasticsearchのデータをwaiting状態で待っていました。
ソースコードを見ると、Elasticsearchはリクエストを処理する際に非同期で呼び出して結果を待つと書かれています。
timed-waiting状態のスレッドはなぜ多かったのか？#
合計190個のスレッドがHikariCPのコネクションを取得するためにtimed-waiting状態にありました。
例えばThread1〜Thread9+が同時にHikariDataSource.getConnection()メソッドを呼び出した場合、Thread1〜Thread5だけがコネクションを取得し、残りはtimed-waiting状態で指定された時間（hikari.connection_timeout デフォルト30秒）の間、返却されたコネクションを取得するために待機します。
なぜTomcat 200スレッドとHikariCP 10コネクションがボトルネックになったのか？#
現在テストで使用しているサーバーのスペックはvCPU 2個、メモリ8GBの単一インスタンスです。
- サーバーインスタンスのCPU数に対してTomcatスレッドの数が多すぎます。 基本的にアプリケーションサーバーはI/O Bound処理がほとんどですが、2個のCPUに対して200個のスレッドは多すぎると考えられます。
- リクエストを処理するスレッドは200個なのに対し、HikariCPのコネクションは最大10個です。 コネクションを取得できない多数の残りのスレッドは待機することになり、これが最終的にリクエストとレスポンスの間の処理時間が増加する問題につながります。
設定を変えるとどれくらい改善されるのか？#
適切なスレッド数とコネクション数の決め方を調べましたが、決まったルールはないようでした。
I/O Boundの処理は一般的にCPU使用量よりもネットワークI/Oのような待機時間が多い処理に依存します。そのため、CPUコア数より多くのスレッドを作成してもコンテキストスイッチのコストは相対的に小さいです。
それならば、コネクション待ち時間を減らすためにスレッドとコネクションプールのサイズの差を調整して、複数回のテストを通じて比較してみます。
結果を確認すると：
- Tomcatのmax-thread：60個
- HikariCPのmax-connection-pool：40個
上記の設定値を適用したときに応答時間が約200msと最も速い応答時間が出ました。
目標との比較： GET 200msは目標の平均応答時間 < 200msに到達しました。デフォルト設定（Tomcat 200、HikariCP 10）比較で5倍の改善です。
画像には追加していませんが、Tomcatのmax-thread：30個、HikariCPのmax-connection-pool：20個の場合もテストしました。しかし別の問題点があったので、以下で別途確認します。
コネクションプールを増やすとDBは大丈夫か？#
HikariCPのコネクションプールサイズを増加させてDBのコネクション数を高く維持することは、基本的にDBに負荷をかけます。
しかし見ての通り、大きな有意な差はありませんでした。runningに該当するコネクションのほとんどは1〜2個程度しか必要なく、DBインスタンスのCPU使用量が若干増加しました。
応答時間改善の代償として何が増えたのか？#
応答時間は減少しましたが、runnable状態のスレッド数とアプリケーションサーバーのCPU負荷が若干増加しました。
なぜPOSTリクエストはまだ500msだったのか？#
ここまで実際の状況を想定して、リクエストの比率はGET 90%、POST 10%に設定しました。そしてproductを保存するときのMySQLとElasticsearchのデータ同期はアプリケーションで直接管理する最もシンプルな方式を選びました。
コードレベルでは、1つのスレッドがElasticsearchにデータを保存した後に続けてMySQLにデータを保存します。
Elasticsearchのデータ保存時に即時のレスポンスが必要でなければ、この処理を非同期処理にすることで応答時間を短縮できると考えました。
結果を確認すると、GETリクエストは2回のテストでいずれも200ms程度を維持し、POSTリクエストは約500msから125msまで減少しました。
最終結果はどう変わったのか？#
| リクエスト | 改善前 | 改善後 | 目標 | 改善率 |
|---|---|---|---|---|
| GETリクエスト | 1秒 | 200ms | < 200ms | 5倍改善、目標達成 |
| POSTリクエスト | 1200ms | 125ms | < 200ms | 10倍改善、目標達成 |
VUser 300名という極限の負荷でもGET 200ms、POST 125msを達成しました。現実的なピーク（15 RPS）基準では目標を十分に超過達成できるレベルです。
3回にわたるパフォーマンス改善はどのように続いたのか？#
| ステージ | GET応答時間 | POST応答時間 | TPS | Error Rate |
|---|---|---|---|---|
| MySQL FullText（2回目） | 30秒以上 | - | 2.1 | 51.3% |
| ES導入（2回目） | 876ms | 1,210ms | 179.6 | 0% |
| スレッド/コネクションのチューニング（3回目） | 200ms | 125ms | ~300 | 0% |
| 目標 | < 200ms | < 200ms | > 15 | < 0.1% |
追加で確認したトレードオフと後続課題#
ここまでが核心的な改善結果で、以下はテストを繰り返しながら追加で確認したトレードオフと後続課題です。
重いAPIはなぜ他のAPIまで遅くするのか？#
この現象の原因はGrafanaダッシュボードの欠損（断絶？）現象の記事で扱いました。
上記の記事で原因を把握したところ、パフォーマンステストの過程ですべてのスレッドがリクエストの処理に使われることでスレッドの返却にも時間がかかるようになっていました。
これによりPrometheusのメトリクスを取得するリクエストに対するスレッド取得時間が増加し、最終的に応答時間も増加する現象が現れました。
この現象はPrometheusのリクエストだけでなく、他のAPIのリクエストにも現れると考えてテストを行いました。
従来はElasticsearch関連リソースであるproductに対するGETとPOSTリクエストのみを処理していましたが、今回はこれとは無関係の他のリクエストをシナリオに追加しました。
結果はすべてのリクエストの応答時間が増加し、800ms以上かかりました。（スレッドプールとHikariCPコネクションプールを調整する前のテスト結果です。）
赤いボックスで囲まれたGET /store、GET /store/{store_id}リクエストは、単独でテストした場合に100〜200ms程度の平均応答時間を示す非常に軽いリクエストです。
しかし比較的重い処理であるGET /productリクエストとPOST /product/newリクエストと一緒にテストを行うと、最終的にリクエストの応答時間が増加する問題につながりました。
この現象が起きた理由はSpring MVC + TomcatがブロッキングI/O方式で動作するからです。
リクエストを処理するとき、Tomcatスレッドがサーブレットコンテナへのリクエストをそれぞれ1件ずつ受け持って処理し、そのロジックが終わるまでスレッドを占有します。そのためそのスレッドはElasticsearchとDBのI/O処理が終わるまで、他のリクエスト処理に使われずに待機することになります。
このため最悪の場合、特定のAPIのリクエストが長時間I/O処理に縛られると、Tomcatのスレッドプールが枯渇し、他のリクエストまで待機しなければならない状況になります。
これを解決するには：
- ノンブロッキング（Non-Blocking）I/Oベースのサーバーアプリケーション（Spring Webflux）を構成する
- スレッドプールを分離する
- サーバーを分離する
などの方法を検討できます。
スレッドを30個に減らすとなぜRPSが下がるのか？#
Tomcatのmax-thread：30個、HikariCPのmax-connection-pool：20個の設定値を適用したとき、応答時間がやや速くなりました。
しかし1つ気になる点がありました。
max-thread 30個、HikariCPのmax-connection-poolが20個の場合、1秒あたりの処理量（RPS）はむしろ低くなりました。
簡単に説明すると、スレッド数を減らすとコンテキストスイッチやコネクションの競合といったオーバーヘッドが減ります。そのためCPUの使用量も減り、少ない数のリクエストだけがサーバー内部のリソースを余裕を持って使えるため、単件の応答時間は速く出ることができました。
しかし同時に受け入れられるリクエストが制限されるため、多くのリクエストが来るとスレッドプールが満杯になって新しいリクエストを速く処理できなくなります。その結果RPSが低い結果になりました。トレードオフの現象です。
スレッドを200個に増やすとなぜまた遅くなるのか？#
- Tomcatのmax-thread：200個
- HikariCPのmax-connection-pool：180個
ここではスレッドだけを200個に増やしたのではなく、前述のボトルネック要因だったTomcatのスレッド数とHikariCPのコネクションプールサイズの大きな差を縮めるために、HikariCPのコネクションプールも180個に増やしました。つまり、デフォルト設定のように200個のリクエストスレッドが10個のコネクションを待つ状況ではなく、コネクション取得待ち自体はできるだけ減らした状態で再び遅くなったケースです。
この場合はRPSの差はほとんどありませんでしたが、応答時間がかなり長くなりました。
その理由を上記のトレードオフの状況と同様に、スレッドが増加してCPUなどのリソースの競合がより頻繁になり、OSレベルでのコンテキストスイッチのコストが増加して応答時間が長くなったと考えました。
しかしさらに調べてみると、従来の問題であったtimed-waiting状態のスレッドは減りましたが、むしろwaiting状態のスレッドは増加していました。
スレッドダンプを分析してみると、180個のwaitingスレッドのうち140個のスレッドがElasticsearchの非同期レスポンスを受け取るためにこの状態にありました。Elasticsearchの総同時接続は30個であることは上でソースコードを示しました。140個のスレッドが30個の接続を取得するために競合が発生したと見られます。
また、Connection Usage Timeが非常に高くなりました。コネクションプールの数が余裕があったためConnection Acquire Timeは低く出ましたが、その後の使用時間が大きく出ました。
runnableスレッドを確認するとMySQLからデータを読み込んでいるスレッドは他の場合と同様に最大4個ほど現れました。コネクションを取得した後なぜ速く処理できないのか、waitingスレッドを含めて関係をもう少し詳しく確認する必要があります。
結論：デフォルト値は出発点に過ぎなかった#
最初にAPIを開発したとき、単純にレビュー数をproductとreviewテーブルをJOINして欲しい結果だけを取得すれば十分だと考えていました。
しかし全文検索インデックスを使う中でクエリの実行時間が大幅に増加する問題が発生しました。実行計画を分析してクエリの構造を改善して実行時間を短縮しましたが、まだ問題が残っていました。
APIで提供しなければならない要件が増えるほど、これを無理やりクエリに追加していくことでクエリが複雑になる問題でした。
また、productテーブルを探索することは全文検索を使う場合だけでなく、様々な場合にも使われうるものでした。
その都度、複雑なサブクエリやJOINを通じてreviewの数とtagを取得するクエリを書くことは非効率だと判断し、プロセスとテーブル構造をより柔軟に再利用できるよう改善する必要性を感じました。
しかしテーブル構造を変更すると新しいデータを入れなければならず、以前のテーブル構造と異なるデータを持つ状態でクエリ時間を比較することは不適切だと判断しました。より正確な基準を立てようと悩んでいる中で、最初から解決しようとしていた問題が何だったかを振り返り、そのクエリを含むAPIのパフォーマンスを改善することが望んでいた目標だったと気づきました。
最初はクエリチューニングだけで問題を解決しようとしました。しかしクエリチューニングは問題を解決するための複数のツールの一つの方法であり、問題そのものではありませんでした。その後、より広く問題を定義すると考えられる選択肢が増え、既存のAPI開発方式の問題点も把握することができました。
そして結果的に使用可能なレベルのAPIを開発することができるようになりました。
ただし負荷テストを確認する中で、まだ解けていない疑問が1つ残りました。仮想ユーザー（VUser）300名が同時にトラフィックを発生させる中でTomcatのThread Poolサイズを60個に減らした場合、残り240個のリクエストはスレッドを取得するために競合するのではないでしょうか？ この疑問はこの実験を理解するうえで続きとなる重要なポイントだったため、次の記事ではTomcat NIO Connectorの観点から続けて確認しました。