はじめに
これはあくあたん工房アドベントカレンダー 2024 13日目の記事です。他の記事も面白いので、是非見ていってください。
今回のスコア
今年も過去回↓と同じくtaxio、shanpuと3人でチームツナ缶として出場しました。
最高得点2万点くらい、最終スコア17110点で、おそらく80位前後くらい58位（ChatGPT調べ）くらいでした（failが多かったよう）。惨敗です。
Grafana・Loki活用Tips
やっていることは前回と大きく変わらないのですが、いくつか改善を入れているのでそれを紹介します。
表示範囲内のログ全てから統計値を計算する
例えば過去30分以内のnginxのログデータから、レスポンスタイムの統計を取りたいとします。↓のようなダッシュボードです。
前回のISUCON参加時のダッシュボードでは例えば表示範囲内のログ行のカウント方法がよく分からず、↓のようなクエリを組んでいました*1。
sum by (uri_normalized, method) (
cont by (uri_normalized, method) (
count_over_time(
{app="nginx", type="accesslog"}
| regexp `$accesslog_pattern`
| __error__ = `` [$__auto]
)
)
)
$__auto というのはGrafanaの自動変数の一つ*2で、Grafanaがグラフを表示する際の step の値を元に設定されます*3。
つまり各step（例えば1秒）ごとにアクセスログをカウントし、その結果をまた別のパラメータごとにカウントし直し、最後に足すという手順になっています。正規表現のパースと合わせてこのクエリは非常に遅く、前回は競技終盤ではこのダッシュボードは見れる状態ではなくなっていました。さらに足すだけなら良いのですが、全体から90パーセンタイルのレスポンスタイムを求めるといったクエリが表現できず困っていました。
Grafanaには $__range という自動変数があり、これは今設定している表示範囲が入ることがわかりました。
https://grafana.com/docs/grafana/latest/dashboards/variables/add-template-variables/#__range
つまり、 2024-12-08T00:00:00Z から 2024-12-08T01:00:00Z を表示範囲としていると、 $__range は 1h になります。計算するクエリをinstantクエリ*4とし、 $__range を使うことで「表示範囲内のログ全てを対象にしたクエリ」が書けます*5。
sum by (uri_normalized, method) (
count_over_time(
{app="nginx", instance=~"$instance", type="access"}
| json
| __error__ = `` [$__range]
)
)
これを活用すると90パーセンタイルのレスポンスタイムタイムは以下の様に計算出来ます。めちゃくちゃシンプル。
quantile_over_time(
0.90,
{app="nginx", instance=~"$instance", type="access"}
| json
| __error__ = ``
| unwrap request_time [$__range]
) by (uri_normalized)
実際、1回のベンチマーク試行では数秒で表示できるので競技終盤でも使える状態でした。
レスポンスが遅かったログを特定する
ISUCONではあるエンドポイントについてレスポンスタイムの最小値と最大値の差が大きいとき、それを引き起こすパラメータを特定したくなるのではないかと考えていました。
LogQLにsortおよび sort_desc という機能はあるのですが、これはMetrics Queryつまり unwrap request_time などとした場合のソートができるだけです*6。「レスポンスタイムが遅いログ上位N件だけ表示する」みたいなクエリは難しいようです。しかしいくつかの機能を組み合わせることで概ねその機能を実装出来ました。
着目したのは以下の特徴です。
- LokiのLogQLはログをパースしてN秒以上のresponse timeを持つログを取り出せる
- 扱える行数は非常に大きい
- Grafanaのテーブルデータとしてログを表示すると、そのラベルの値に基づいてソートできる
- 扱える行数は最大でも5000
- LokiのLogQLはログのラベルからNパーセンタイルなどのレスポンスタイムを計算出来る
つまり、まずNパーセンタイルのレスポンスタイムを計算し、それ以上のレスポンスタイムを持つログを抽出、数を絞ってGrafanaの機能でソートすることで遅い順にN%のログを取り出せます。
これをUI上で無理なく表現するため、リクエストの統計値のサマリを出すダッシュボードからGrafanaのData Linkを使って別ダッシュボードへ飛ばします。
まず、Overridesを使ってテーブルの特定のカラムにだけData linkを設定します。複数設定も可能です。
遷移先ダッシュボードのVariableに値を渡すため、以下の様にData Linkを設定しました。ここでは対象のエンドポイントの正規表現、対象にするインスタンス、90パーセンタイルのレスポンスタイムを数値として*7、そして今表示している時間範囲を渡しています。渡せる値などは以下のページが参考になります。
遷移先のダッシュボードではnginxのログをフィルタしてN秒以上のログを抽出し、Grafanaのテーブル機能でソートします。このとき、1000件しか取得していないのでフィルタした結果が1000件を超えているとソートが不完全になります（取得した1000件の中に最悪値が含まれるとは限らないため）。そういう場合は閾値を手動で調整します。
Grafanaのテーブルパネルはログパネルと違ってクリック時に詳細を表示するみたいなことが綺麗にできなかったので、そこから更にrequest idやクエリパラメータまで含めたURIの一致でログを絞り込むダッシュボードに遷移するようにしています。
スロークエリログの統計値も計算したい
昨年は生のスロークエリログをそのままGrafana Cloudにアップロードしていたのですが、クエリが正規化されていないのでどういうクエリが遅かったとかを解析出来ませんでした。今年はその反省を活かし、pt-query-digestを使ってスローログの正規化を試みました。
pt-query-digest --no-report --output secure-slowlog のようにすると、pt-query-digestは統計値を計算せずただただクエリを正規化してスロークエリログ形式で出力するようになるので、単にMySQLが吐く生のスロークエリログをtailしてstdinから流し込むだけで良い感じの出力を得られます。本番では以下の様なsystemd unitを用意しました。
[Unit] Description=Normalize slow logs by pt-query-digest [Service] Type=simple User=mysql ExecStartPre=/bin/bash -c '[ -f "/tmp/slow_query.log" ] || touch /tmp/slow_query.log' ExecStart=/bin/bash -c "tail -F -n +1 /tmp/slow_query.log | pt-query-digest --no-report --output secure-slowlog" Restart=always [Install] WantedBy=multi-user.target
Grafana Alloy*8を使って、昨年と同様にスロークエリログを正規表現でパースします。
// スロークエリログの処理本体 loki.process "slowquery" { // ここでGrafana Cloudやその前段のフィルタステップに流す forward_to = [argument.write_to.value] // マッチするログだけを処理する stage.match { selector = "{app=\"slow-query-normalizer.service\"}" stage.static_labels { values = { app = "mysql", type = "slowquery", } } // スロークエリログは複数行にまたがっているのでまとめる stage.multiline { firstline = "^#\\sTime:.*$" } // 正規表現でスロークエリログをパース、query_timeなどを抽出 stage.regex { expression = "#\\s*Time:\\s*(?P<timestamp>.*)\\n#\\s*User@Host:\\s*(?P<user>[^\\[]+).*@\\s*(?P<host>.*]).*\\n#\\s*Thread_id:\\s*(?P<id>\\d+)\\n#\\s*Query_time:\\s*(?P<query_time>\\d+\\.\\d+)\\s*Lock_time:\\s*(?P<lock_time>\\d+\\.\\d+)\\s*Rows_sent:\\s*(?P<rows_sent>\\d+)\\s*Rows_examined:\\s*(?P<rows_examined>\\d+)\\n(?P<query>(?s:.*))$" } stage.timestamp { source = "timestamp" format = "RFC3339Nano" } // packでLokiが認識できる形にラベルをまとめてログ行として挿入 stage.pack { labels = [ "query_time", "lock_time", "rows_sent", "rows_examined", "query", ] ingest_timestamp = false } } } // Journalログのいくつかのパラメータを取り出す loki.relabel "journallog" { forward_to = [] rule { source_labels = ["__journal__systemd_unit"] target_label = "app" } rule { source_labels = ["__journal_priority_keyword"] target_label = "level" } } // Journalログを読み出してルールに従ってreleabelした後、冒頭のprocessステップに流し込む loki.source.journal "journallog" { forward_to = [loki.process.slowquery.receiver] max_age = "10m" relabel_rules = loki.relabel.journallog.rules labels = { job = "loki.source.journal", } }
ポイントはmultilineで複数行のデータを一つにまとめることと、packを使うことです。LogQLには unpack という機能があり、長らく謎だったのですがこれはpromtailやGrafana Alloyの持つこの pack という機能を使ってインジェクトしたパラメータを取り出す機能だったのです。
以下の様なログがあるとします。
2024-12-01T00:00:00Z info message=hoge response_time=0.001 2024-12-01T00:00:01Z info message=fuga response_time=0.012
ここで、response_timeは非常にカーディナリティの高い値であるとします。Lokiのログラベルは非常に高いカーディナリティを持つと非効率になってしまうことから制限がかけられており、そのまま投入してしまうとリミットに触れてしまう可能性があります*9。こうなるとLogQLの実行時にパースすることを考える必要があります。例えば以下の様に pattern や、 regexp を使うことになるでしょう。
{app="sample"}
| pattern `<time> <level> message=<message> response_time=<response_time>`
| __error__ = ``
| response_time > 0.1
patternやregexpを毎回記述するのは面倒です。特にGrafanaのExploreのようなユーザがアドホックにクエリを組んで可視化したいときにも必要になることが有り、不便です。 pack はPromtailやAlloyに実装されている機能で、LogQLが識別しやすい形でラベルを埋め込んでおき、実行時に unpack することで pattern や regexp を使わずに非JSONなログ行からパラメータを簡単に取り出せます。
Alloyの処理段階でパース・packすると、先の例のログを以下の様な内容のログ行に変換してくれます。
{"_entry": "2024-12-01T00:00:00Z info message=hoge response_time=0.001", "response_time": "0.001"} {"_entry": "2024-12-01T00:00:01Z info message=fuga response_time=0.001", "response_time": "0.012"}
これをLogQLでunpackすると、元のログ行に追加のラベルを付与した状態で展開してくれるので、response_time に基づくフィルタなどを記述できます。
{app="sample"}
| unpack
| __error__ = ``
| response_time > 0.1
ログ行として埋め込んでいるのでラベルのカーディナリティ制限は問題になりません。元のログ行はそのまま保持するので再利用性も良いです。ただしログ行の内容が純増するので、巨大になりすぎないように注意しましょう。
こうしてスロークエリログのQuery_timeやLock_timeを取り出して pack し、Grafana上でLogQLを書いて unpack することで、正規化されたクエリごとの90パーセンタイルの処理時間などを計測し、遅い順にソートしたりできるようになります。
当日やったこと
自分のやった内容です。
- ~11:00：環境構築・解析基盤の準備
- ~12:00：index張ったりownerGetChairsの重いクエリをちょっとマシにした
- ~14:00：複数台構成を組みながらmatcherの重要性に気付く
- ~16:00：ベンチマークが全く通らず色々切り戻して初期状態に戻る
- ~17:00：これまでの作業の復元
- ~17:30：matcherが叩くintervalやRetryAfterの微調整をしたがfailしまくる
- ~18:00：再起動して壊れないか見たり色々
- isuride-matcherをdisableする必要があることに気付いてナイス
やや初期構築に時間をかけすぎたなと感じています。そして細かいミスが多すぎました。さすがに反省。
途中あまりにもベンチマークが通らず、ほぼ初期状態まで切り戻したことで大幅に時間をロスしてしまったのが痛かったです。 複数台構成を組んだ際、他のメンバーが自由に作業できるよう共有のDBインスタンス一台と、それを参照する各々のアプリ用インスタンス2台としていました。アプリが非同期に処理を実行していたためマッチングの処理内容によっては容易に壊れうる状態にしてしまいました。ちゃんとmatcherのことに気付いていながら思い至らなかったのは反省です。
今後の展望
遅いリクエストを特定できるようになったので、OpenTelemetryによる分散トレーシングと組み合わせれば、そのとき実行されたアプリ側の処理や発行されたSQLまで追いかけられて便利なのではと思っています。 またnonyleneくんに先に行かれてしまった……。
ただオブザーバビリティにかける時間が増えるほど、問題を解く時間は減ってしまいます。今は最初期に設定を入れたら後はノーメンテであり、どういうバランスを取るか悩ましいです。
GrafanaやLokiは便利ですがちゃんと知らないと上手く可視化できません。何かヒントになっていれば嬉しいです。次は優勝するぞ。
*1:前回はnginxのログをLTSV形式で出してaccess_patternという変数に入れた正規表現でパースしていました。これもかなり遅い原因の一つでした
*2:Loki template variables | Grafana documentation
*3:Loki query editor | Grafana documentation
*4:今の表示範囲の最新時間について1回だけ実行されるクエリ
*5:今回はnginxにJSON形式でログを吐かせることにしたので、regexpではなくjsonを使っています。シンプルでこの方が明らかに取り回しがよい！
*6:機能としてはPrometheusのsortと同じです。 https://prometheus.io/docs/prometheus/latest/querying/functions/#sort
Prometheusでは最近experimentalな機能としてsort_by_labelなどが実装され始めたようです。 https://prometheus.io/docs/prometheus/latest/querying/functions/#sort_by_label
*7:numericにしないと、50msのように表示されている値そのままになってしまいます。
*8:昨年はGrafana Agent Flow modeでしたが、これはメンテモードとなり後続の製品としてGrafana Alloyが出ました。だいたい一緒で、ちょっとだけ違うという感じなので乗り換えはそこまで大変では無いと思います。Web UIがあって、experimentalではあるもののデバッグモードを有効化するとリアルタイムにどういうデータが流れてきてフィルタされたり加工されたりしているか見れるので便利です
*9:https://poyo.hatenablog.jp/entry/2023/11/26/170000#%E4%BD%95%E3%81%A7%E3%82%82%E3%83%AD%E3%82%B0%E3%81%AE%E3%83%A9%E3%83%99%E3%83%AB%E3%81%AB%E4%BB%98%E4%B8%8E%E3%81%99%E3%82%8B%E3%81%A8%E6%AD%BB%E3%81%AC
