バックエンド屋の性能最適化 実戦（3）：Grafana と Prometheus のクエリ実例

前置き

これ、もしかしてあなたのことでは。（暴言）

ちょっと待って、離れないで！ここまでたくさんの資料を読んで、あなたも初代エルデンロード・ゴッドフレイのように、しちめんどうな作法にもう飽き飽きしているのではないでしょうか。彼のように服を脱いでホーラ・ルーとして還俗しろとは勧めませんが、Grafana と Prometheus に関する実際のケースをいくつか見ていきましょう。図解付きで説明すれば、使い方がもっとはっきり分かるはずです。以下の記事には複数の例示画像が含まれます。

負荷テスト下での観測

よくある Grafana Dashboard はこんな見た目です。可視化されたグラフを通じて、システムの現在の指標値を把握できます。例えば、この画像は私がローカルで負荷テストを行った結果です。左上ではシステムの現在の RPS、レイテンシの状況、データベースのコネクションプールの状況などが確認できます。中でも左下のグラフを見ると、負荷が上昇するにつれて active connection が増え、idle connection と交差しているのがはっきり分かります。これは負荷が上がり始めたことを示しています。その後、active connection が max_connection まで達すると、pending connection が徐々に増え始め、最終的には max_connection の数倍にまで膨らんでしまいました。これはデータベースのコネクションプールの数が足りなくなっていることを明確に示しており、右上の HikariCP の待機数もそれを裏付けています。

さらに、右側の Java Heap 使用量にはあまり変化がなく、この時点でのボトルネックは GC とはあまり関係がないことが分かります。ここまで分かれば、@Transaction が長く保持されていないか、データの取得量が多すぎることが原因ではないか、といった具合にさらに深く調べていけます。Grafana があることで、性能最適化のこの道のりで無駄な回り道をかなり減らせます。

単一 API の P95 レイテンシを照会する

例えば、/api/v1/ticket という API の P95 レイテンシ(95% のリクエストがこの時間以内に収まる)を知りたいとします。Grafana ではこのような PromQL を書くことになります。

histogram_quantile(0.95, sum by (le) (rate(
  http_server_requests_seconds_bucket{uri="/api/v1/ticket"}[5m])))

負荷テストの状況下で、この API のレイテンシは上昇を続け、最終的に 480 ミリ秒まで達しました。これは 5% のユーザーが 480 ミリ秒、あるいはそれ以上のレイテンシを経験することを意味します。数字だけ見ればそれほど高くないように聞こえるかもしれませんが、重要なのは数値そのものではなく、私たちが測定した手法そのものです。数値そのものより重要なのは傾向です。P95 レイテンシが単発の急上昇ではなく短時間で持続的に上昇していく様子が見えた場合、それは通常どこかのリソースが押し潰されつつあることを意味します——コネクションプールが満杯になっている、キャッシュの失効でリクエストがすべて DB に向かっている、あるいは JVM が頻繁な GC に陥っている、などです。この時点でいくつか折れ線を追加して突き合わせてみると、当てずっぽうではなくボトルネックを実際に特定しやすくなります。

一般的に、API レイテンシの P95 はこのようなおおまかな基準で判断できます。

あるAPIの処理時間が知りたいだけなら、もうそれは手に入りました。しかし、さらに一歩進んで考えてみましょう。あるAPIに複数の要因が絡んでいたら、例えば内部サービスの呼び出し、ファイルの読み込み、外部サービスへのリクエストが同時に発生していたらどうでしょうか。API が遅いと分かったあとに、どの部分が遅いのか具体的に分かるでしょうか。ログを一つひとつ仕込んでテストするのでしょうか。そのためにどれだけのログを出力すれば良いのか、逆に無効な大量データを生み出してしまわないでしょうか。

そこで、もし可能であれば、もっと詳細な分析手法が必要になります。そしてその部分は、Grafana + Prometheus がしっかりカバーしてくれます。

特定の処理区間の処理時間を照会する

特定の処理区間の処理時間を調べたいなら、多少のコードを書くことは避けられません。まず、監視したい区間に MeterRegistry というBeanを注入する必要があります。コード例はおおよそこのような形になります。

class A {
  public void someMethods() {
   // MeterRegistry を注入

    Timer.Sample coreSample = Timer.start(meterRegistry);
    /////////// 何らかの時間のかかる処理
    coreSample.stop(meterRegistry.timer("ticket.purchase.core"));

  }
}

こうすることで処理時間が記録されるようになり、Prometheus 側では "ticket.purchase.core" というタグを使ってこの処理の時間を照会できます。しかしまだ十分ではありません。私たちの API は P95 の処理時間を照会していたことを覚えているでしょうか。整合性を保つため、もう一つ設定を追加して histogram_quantile() に対応させる必要があります。

management:
  metrics:
    distribution:
      percentiles-histogram:
        "[http.server.requests]": true
        "[ticket.purchase.core]": true
      percentiles:
        "[http.server.requests]": [0.5, 0.95, 0.99]
        "[ticket.purchase.core]": [0.5, 0.95, 0.99]

設定が終わったら、次の PromQL でこの処理区間の処理時間を照会できます。

histogram_quantile(0.95, sum by (le) (rate(
  ticket_purchase_core_seconds_bucket[5m])))

一つ注意しておきたい点があります。コードの中では ticket.purchase.core(ドット区切り)と命名していますが、PromQL で照会するときには ticket_purchase_core_seconds_bucket(アンダースコア区切りで、さらに _seconds_bucket という接尾辞が付く)に変わっています。これは打ち間違いではなく、Micrometer がデータを Prometheus に渡す際に適用する命名規則の変換です——Prometheus の metric 名にはドットを含められないため、Micrometer が自動的にドットをアンダースコアに変換し、さらにその指標の単位(ここでは秒)や、それが histogram かどうかに応じて _seconds や _bucket といった接尾辞を補います。コードに書いた元の名前のままで照会しようとすると何も出てきませんので、必ず Prometheus 側の実際の命名形式に変換する必要があります。

以下が実行結果です。

今回の実験結果はあまり理想的とは言えませんが、これはあくまで一例にすぎません。今後はこの手法を使って Prometheus と組み合わせ、特定の処理区間の処理時間を分析できるようになれば、こうした評価をもっと安心して行えるようになるはずです。