p50 と p95 が同じ値になる理由

一言でいうと

LogQLのメトリクスクエリは、ログを数値に変えます。ところが、パーサーが作ったラベルがそのまま系列を分けるため、ラベルを整理しないと、パーセンタイルや合計が静かに無意味になります。

なぜ必要なのか

あるチームが、レイテンシのヒストグラムをまだ計装できていないサービスのp95を、Lokiで測ろうとしました。ログにはdur_ms=...が出力されているので、quantile_over_time(0.95, {app="checkout"} | logfmt | unwrap dur_ms [5m])でいけそうでした。グラフはきれいに描かれ、数字ももっともらしく見えました。

問題は、p50とp95がほとんど同じに出ることでした。ログには確かに1.5秒の裾があるのに、p95は60ミリ秒台にとどまっていました。原因は、ログに一緒に出力されていたbytes=...フィールドでした。その値が行ごとに違うため、logfmtが作ったbytesラベルが1行につき1系列を作ってしまいました。系列ごとにサンプルが1個しかないので、どのパーセンタイルを尋ねても、その行の値がそのまま出ます。

どう動くのか

LogQLのメトリクスクエリには、2つの系統があります。

ログ範囲集計は、行を数えます。count_over_time、rate、bytes_over_time、bytes_rateがここに入ります。パーサーは不要で、必要ならフィルターで数える行を選びます。

unwrap範囲集計は、行から取り出した数値を扱います。| unwrap <라벨>(プレースホルダーはラベルです)でどの値を使うかを決めたあと、avg_over_time、max_over_time、quantile_over_time、sum_over_time、rate_counterをかけます。値が単位付きの文字列なら、duration_seconds(...)やbytes(...)で包んで変換できます。

どちらの系統でも、系列の同一性はラベルが決めます。ストリームラベルだけでなく、そのクエリでパーサーが作ったラベルまですべて含まれます。そのため、unwrapを使うときは、ほとんど常にラベルを整理する必要があります。| keep <쓸 라벨>(プレースホルダーは残すラベルです)で残すものだけを残すか、| drop <버릴 라벨>(プレースホルダーは捨てるラベルです)で値がバラバラなフィールドを取り除きます。あるいは外側にsum by (...)やmax(...)のような集計をかぶせて、系列をまとめます。

ここで、Prometheusと違う点が1つあります。Prometheusのhistogram_quantileは、あらかじめバケットに要約されたデータからパーセンタイルを推定しますが、Lokiのquantile_over_timeは元の値をすべてスキャンします。そのため、より正確なかわりに、はるかに高価です。広い区間にかけると、読む量がそのままコストになります。

最後に、ログでメトリクスを作ることは一時しのぎだということを忘れないほうがよいです。同じ数字をメトリクスとして出力すれば、1行が数バイトに縮み、クエリも定数時間に近づきます。ログベースのメトリクスは、計装がないときや、過去をさかのぼる必要があるときに使う道具です。

現場での姿

最もよく起きる事故が、上の「系列の爆発」です。症状が特徴的です。エラーもなく、グラフも描かれるのに、p50とp99がくっついて動きます。疑わしければ、系列数からまず数えます。系列が行数に近ければ、答えが出ました。

2つ目は、ダッシュボードのコストです。quantile_over_timeパネル1つを24時間区間でかけて30秒ごとに更新すると、そのパネルだけで、1日分のログを30秒ごとに読み直します。ログベースのパーセンタイルのパネルは、区間を短くしておき、長い区間が必要なら、レコーディングルールであらかじめ畳んでおくほうがよいです。

3つ目は、単位です。dur=1.5sとdur_ms=1500が同じサービスで混ざって出てくると、unwrapは両者をそのまま足します。フィールド名に単位を埋め込んでおく習慣が、この事故を防ぎます。

次のラボですること

2つのサービスのログをPodのLokiに入れ、行を数えるクエリと、値を取り出すクエリを、それぞれ作ります。unwrapでp95を求めようとして、系列が行数の分だけ分かれる様子を自分で見て、系列数を数えたあと、ラベルを整理して、p50とp95が分かれることを確認します。最後に、同じ数字をメトリクスとして出力した場合と比べて、何を選ぶかを、根拠とともに書きます。