ログから p95 を測ったら p50 と同じ数字が出た

目標

LogQLの2種類のメトリクスクエリを自分で投げてログを数値に変え、抽出されたラベルが系列を分割して、パーセンタイルを無意味にする現象を再現したあと、直します。

なぜ重要なのか

メトリクスがないサービスのレイテンシやエラー率を急いで知りたいとき、ログはすでにそこにあります。LogQLのメトリクスクエリは、そのログを数値に変えてくれますが、罠が1つあります。系列の同一性を決めるラベルに、そのクエリでパーサーが作ったラベルまで入るということです。値が行ごとに異なるフィールドが1つでも抽出されると、系列が行数の分だけ分割され、系列ごとにサンプルが1つしかないので、どのパーセンタイルを尋ねても同じ値が出ます。エラーも警告もなく、グラフだけがきれいに描かれるため、何か月も見つかりません。そして、ログベースのメトリクスは、クエリのたびに元データを読むので、ダッシュボードにかける前に、読む量を一度測ってみる習慣が必要です。

ステップ

/root/lk-metricsでLokiを起動し、date +%sを/root/lk-metrics/anchor.txtに書いたあと、python3 /opt/lab/d5/gen.py metrics "$(cat anchor.txt)"でデータを入れてください。そして、基準時刻をtimeとして指定してsum by (app) (count_over_time({app=~"checkout|search"}[1h]))を投げ、2つのサービスの行数を/root/lk-metrics/01-boot.txtにcheckout=<정수>とsearch=<정수>の2行で書いてください(プレースホルダーは整数です)。
checkoutサービスでstatusが500の行の毎秒の発生率を、1時間の区間で求めてください。クエリは/root/lk-metrics/02-rate.logql、値は/root/lk-metrics/02-rate.txtにrate=<소수 여섯째 자리>の1行で書きます(プレースホルダーは小数第6位までの値です)。結果が1つの系列で出るように、外側をsum(...)でまとめてください。
checkoutの1時間のエラー割合(500の行÷全体の行)を求めて、/root/lk-metrics/03-ratio.txtにratio=<소수 여섯째 자리>の1行で書いてください(プレースホルダーは小数第6位までの値です)。クエリは/root/lk-metrics/03-ratio.logqlに書きます。分子と分母をそれぞれsum(...)でまとめて割ると、系列がぴったり合います。
quantile_over_time(0.50, ...)とquantile_over_time(0.95, ...)を、{app="checkout"} | logfmt | unwrap dur_ms [1h]にかけて、それぞれ投げてください。2つのクエリが返した系列数と、最初の系列の値を、/root/lk-metrics/04-trap.txtに4行で書きます。series=<정수>、p50_first=<숫자>、p95_first=<숫자>、lines=<그 구간의 전체 줄 수>です(プレースホルダーは順に、整数、数値、数値、その区間の全体の行数です)。
同じ2つのパーセンタイルを、1つの系列で出るように直して投げてください。クエリは/root/lk-metrics/05-p50.logqlと/root/lk-metrics/05-p95.logqlにそれぞれ書き、値は/root/lk-metrics/05-fix.txtにp50=<숫자>・p95=<숫자>・series=<정수>の3行で書きます(プレースホルダーは数値、数値、整数です)。2つの値がはっきり分かれる必要があります。
/root/lk-metrics/compare.tsvを作成してください。ヘッダーなしで2行で、各行はタブで区切った4つの欄<서비스><탭><줄수><탭><오류비율><탭><p95>(プレースホルダーは順に、サービス、タブ、行数、エラー割合、p95です)です。サービスは順にcheckout、searchで、エラー割合は小数第6位まで、p95は小数なしで四捨五入した整数で書きます。
ステップ5のp95クエリをquery_rangeで1時間の区間に投げて、レスポンス統計の読んだバイト数を測り、/root/lk-metrics/07-cost.txtに3行で書いてください。bytes_per_query=<정수>、refresh_sec=30、bytes_per_day=<정수>です(プレースホルダーは整数です)。1日分は、30秒ごとに1回動くものとして、bytes_per_query × 2880で計算します。
/root/lk-metrics/08-decide.txtに3行を書いてください。choice=の後ろにlogまたはmetricのどちらか、evidence=の後ろに前のステップで測った数字を2つ以上含めた1行、reason=の後ろになぜその選択なのかを、空白を除いて60文字以上で書きます。正解は1つではありませんが、根拠は前のステップの実測値である必要があります。

参考

作業ディレクトリは/root/lk-metricsです。Lokiはステップ1で自分で起動します。
データ生成器は/opt/lab/d5/gen.pyで、metricsデータを書き込みます。採点ツールはこのファイルを読みません。
メトリクスクエリは、/loki/api/v1/queryにtimeを指定して投げ、区間ごとの値が必要なら/loki/api/v1/query_rangeにstepを指定します。模範解答が作るmq.shは便宜上のヘルパーです。
よくある間違い: since=1hや現在時刻で測ってしまいます。anchor.txtの基準時刻をtimeとして指定してください。
よくある間違い: 分子と分母のラベルの集合が異なり、割り算が空の結果を返してしまいます。両側をsum(...)で包むと、ラベルがすべて消えて、ぴったり合います。
メトリクスクエリ・ログクエリ・LogQL概要・HTTP API

2つのサービスのログを入れて、まず行を数える

/root/lk-metricsでLokiを起動し、date +%sを/root/lk-metrics/anchor.txtに書いたあと、python3 /opt/lab/d5/gen.py metrics "$(cat anchor.txt)"でデータを入れてください。そして、基準時刻をtimeとして指定してsum by (app) (count_over_time({app=~"checkout|search"}[1h]))を投げ、2つのサービスの行数を/root/lk-metrics/01-boot.txtにcheckout=<정수>とsearch=<정수>の2行で書いてください(プレースホルダーは整数です)。

メトリクスクエリは、query_rangeではなく/loki/api/v1/queryで投げ、timeをナノ秒で指定します。レスポンスのresultTypeがログクエリと違うことも、一度見てください。sum by (app)が、系列をサービスごとにまとめてくれます。

行を数えるクエリ: 毎秒のエラー

checkoutサービスでstatusが500の行の毎秒の発生率を、1時間の区間で求めてください。クエリは/root/lk-metrics/02-rate.logql、値は/root/lk-metrics/02-rate.txtにrate=<소수 여섯째 자리>の1行で書きます(プレースホルダーは小数第6位までの値です)。結果が1つの系列で出るように、外側をsum(...)でまとめてください。

rateは、区間内の行数を区間の秒数で割ります。500だけを数えるには、パーサーでステータスコードを取り出して、ラベルフィルターをかける必要があります。値がとても小さく出るのが正常です。1時間に数件だからです。

割合は、2つのメトリクスクエリを割り算する

checkoutの1時間のエラー割合(500の行÷全体の行)を求めて、/root/lk-metrics/03-ratio.txtにratio=<소수 여섯째 자리>の1行で書いてください(プレースホルダーは小数第6位までの値です)。クエリは/root/lk-metrics/03-ratio.logqlに書きます。分子と分母をそれぞれsum(...)でまとめて割ると、系列がぴったり合います。

分母にはパーサーは不要です。全体の行を数えれば済みます。分子と分母のラベルの集合が異なると、割り算が空の結果を返すので、両側をsum(...)で包んでラベルをすべて消すのが、最も単純な方法です。

p50とp95がまったく同じに出る

quantile_over_time(0.50, ...)とquantile_over_time(0.95, ...)を、{app="checkout"} | logfmt | unwrap dur_ms [1h]にかけて、それぞれ投げてください。2つのクエリが返した系列数と、最初の系列の値を、/root/lk-metrics/04-trap.txtに4行で書きます。series=<정수>、p50_first=<숫자>、p95_first=<숫자>、lines=<그 구간의 전체 줄 수>です(プレースホルダーは順に、整数、数値、数値、その区間の全体の行数です)。

系列数は、レスポンスのdata.result配列の長さです。その数字を、ステップ1で数えた行数と比べてみてください。なぜ2つのパーセンタイルが同じ値を出すのかは、その比較で一目でわかります。logfmtがこのログで作ったラベルが何と何なのかも、結果のmetricで確認してください。

ラベルを整理すると、パーセンタイルが分かれる

同じ2つのパーセンタイルを、1つの系列で出るように直して投げてください。クエリは/root/lk-metrics/05-p50.logqlと/root/lk-metrics/05-p95.logqlにそれぞれ書き、値は/root/lk-metrics/05-fix.txtにp50=<숫자>・p95=<숫자>・series=<정수>の3行で書きます(プレースホルダーは数値、数値、整数です)。2つの値がはっきり分かれる必要があります。

値が行ごとに異なるラベルを取り除くか、使うラベルだけを残すか、外側を集計で包めば済みます。3つの方法のどれを使ってもかまいません。ただし、系列が1つになる必要があります。どのラベルが犯人かは、ステップ4の結果のmetricを見ればわかります。

2つのサービスを1つの表で比べる

/root/lk-metrics/compare.tsvを作成してください。ヘッダーなしで2行で、各行はタブで区切った4つの欄<서비스><탭><줄수><탭><오류비율><탭><p95>(プレースホルダーは順に、サービス、タブ、行数、エラー割合、p95です)です。サービスは順にcheckout、searchで、エラー割合は小数第6位まで、p95は小数なしで四捨五入した整数で書きます。

ステップ3とステップ5のクエリで、サービス名だけを変えれば済みます。同じデータでも、2つのサービスの裾の形が異なることを、表で確認してください。平均ではなくp95を見て初めて見える違いです。

応用①: このクエリをパネルとしてかけると、どれだけ読むか

ステップ5のp95クエリをquery_rangeで1時間の区間に投げて、レスポンス統計の読んだバイト数を測り、/root/lk-metrics/07-cost.txtに3行で書いてください。bytes_per_query=<정수>、refresh_sec=30、bytes_per_day=<정수>です(プレースホルダーは整数です)。1日分は、30秒ごとに1回動くものとして、bytes_per_query × 2880で計算します。

メトリクスクエリもquery_rangeで投げられ、そのときはstepを指定します。統計は、ログクエリと同じ場所(data.stats.summary)にあります。1日2880回は、30秒周期の1日の回数です。ダッシュボードのパネル1つが、人よりはるかに多くクエリするという意味です。

応用②: ログで測り続けるか、メトリクスとして出力するか

/root/lk-metrics/08-decide.txtに3行を書いてください。choice=の後ろにlogまたはmetricのどちらか、evidence=の後ろに前のステップで測った数字を2つ以上含めた1行、reason=の後ろになぜその選択なのかを、空白を除いて60文字以上で書きます。正解は1つではありませんが、根拠は前のステップの実測値である必要があります。

2つの道の値が違います。ログベースは、計装を直さなくてよく、過去をさかのぼれますが、クエリのたびに元データを読みます。メトリクスベースは、安くて速いですが、あらかじめ出力しておく必要があり、過去はありません。ステップ7の1日に読む量と、ステップ4・5で経験した罠を根拠に使えば、説得力が生まれます。