CloudWatch Logs Insights 集計クエリ入門

AWS CloudWatch Logs をご利用のみなさん、CloudWatch Logs Insights は利用していますか？
自分は CloudWatch Logs の検索記法に慣れていたのもあり、Logs Insights の記法を学習する元気がいまいち起きず、初めの方は filter @message =~ "hoge" みたいなクエリしか使っていませんでした (このクエリは今もよく使います )。

しかしながら、Saved Query 対応などもきっかけに、ここ 1 年くらいで結構 Logs Inshigts の集計クエリを活用する場面も増えたので、集計クエリの使い方のチュートリアルのような記事にまとめてみます。

以下、簡単な API アクセスログみたいなものを想定して、ログデータの集計というシーンにおけるクエリ例やちょっとしたテクニックを紹介していきます。

あるフィールドの値でグルーピングして集計したい

例: 応答 status 値ごとのログ件数をカウントする

まずは非常に基本的な stats コマンドの利用例です。
以下のように status に HTTP status を持つログから、 status の値ごとの発生件数をカウントします。

{"status": 200}

次のクエリで実現できます。

stats count(*) by status

以下のような結果が得られます。

status	count(*)
200	15
400	3

一定時間単位のデータを集計したい

例: 15分ごとのログ件数をカウントする

これもサンプルクエリにもあるくらいの bin 関数を利用した stats の例です。
同様に status に HTTP status を持つログから、 15 分ごとの 200 応答件数をカウントします。

filter status = 200
| stats count(*) by bin(15m)

以下のような結果が得られます。

bin(15m)	count(*)
2020-12-01 15:15:00.000	19
2020-12-01 15:00:00.000	35
2020-12-01 14:45:00.000	32
2020-12-01 14:30:00.000	72

テクニック: filter をせずに条件付きのカウントをしたい

さて、上記の例では先に status = 200 で filter してから集計を行っていました。
これを filter を用いずに行うにはどうすると良いでしょうか。

これは boolean が 0, 1 であることを利用することで、以下のように表現できます。
後述しますが、このテクニックは複数の集計値を扱う場合に有用になってきます。

stats sum(status = 200) by bin(15m)

また、フィールドとして定義した条件式を利用することもできます。

fields status = 200 as is_200
| sum(is_200) by bin(15m)

今の簡単な例では大していいことはありませんが、
複雑な条件を扱う場合や、条件式を再利用する場合などに見通しのよいクエリを書くのに役立ちます。

テクニック: JST で bin(1d) したい

デイリーの集計で利用する bin(1d) は UTC 基準で集約されます。
それで困らないシーンも多いとは思いますが、きっちり日本時間で集計したいこともあると思います。

bin 関数のオプションや @timestamp のタイムゾーン変換を行う関数は現状ありませんが、
@timestamp は Unix timestamp なので、これに直接整数を足して時間操作を行うことができます。

以下のように手動での時間操作と date_floor 関数を利用することで JST 版の bin(1d) と正味同じ挙動を実現できます。

date_floor(@timestamp + 9 * 60 * 60 * 1000, 1d)

あるフィールドの値 × 一定時間単位でグルーピングして集計したい

例: 15分ごとの応答 status 値ごとのログ件数をカウントする

これまでの stats コマンドの利用を組み合わせた例です。
同様に status に HTTP status を持つログから、 15 分ごとの status ごとの発生件数をカウントします。

stats count(*) by status, bin(15m)

以下のような結果が得られます。

status	bin(15m)	count(*)
400	2020-12-01 15:15:00.000	1
400	2020-12-01 15:00:00.000	4
400	2020-12-01 14:45:00.000	3
400	2020-12-01 14:30:00.000	7
200	2020-12-01 15:15:00.000	19
200	2020-12-01 15:00:00.000	35
200	2020-12-01 14:45:00.000	32
200	2020-12-01 14:30:00.000	72

表示結果の調整をしたい

ちょっとデータの次元が増えると表の並べ方を調整したくなります。
sort コマンドや display コマンド、 as キーワードなどを活用できます。

例えば上記の表を以下のように調整してみます。

• 一番左の列を時間にする
• 時間 -> status (desc) の辞書順に並べる
• カウントの列名は total_count にする

stats count(*) as total_count by status, bin(15m) as bin_15m
| sort bin_15m, status desc
| display bin_15m, status, total_count

以下のような結果が得られます。

bin_15m	status	total_count
2020-12-01 15:00:00.000	400	4
2020-12-01 15:00:00.000	200	35
2020-12-01 15:15:00.000	400	1
2020-12-01 15:15:00.000	200	19
2020-12-01 14:30:00.000	400	7
2020-12-01 14:30:00.000	200	72
2020-12-01 14:45:00.000	400	3
2020-12-01 14:45:00.000	200	32

複数項目の集計をしたい

例: 応答時間の傾向について、複数の条件 (avg, p95, etc...) で集計する

先ほどの組み合わせでは stats コマンドの by キーワードの後ろを増やすことで、グルーピングの基準を追加しました。
stats コマンドの by キーワードの手前の集計値を増やすことで、複数の集計項目を取り扱うことができます。

{"response_time": 15}

上のような response_time の値をもつログから

• 平均応答時間
• p95 応答時間
• 1000ms を超えた応答の数
• 1000ms を超えた応答の数の割合

を1クエリで集計します。

stats count(*) as total,
  avg(response_time) as response_avg,
  pct(response_time, 95) as response_p95,
  sum(response_time >= 1000) as over_1s_count
| display response_avg, response_p95, over_1s_count, (over_1s_count / total * 100) as over_1s_rate

sum(response_time >= 1000) の部分は条件付きカウントを利用しています。
仮に filter コマンドで response_time が大きいログだけに絞ってしまうと、count(*) as total で取れる値が 「全体の応答の数」ではなく「response_time が大きい応答の数」になってしまい、全体の応答数などとの比較ができなくなります。

以下のような結果が得られます。

response_avg	response_p95	over_1s_count	over_1s_rate
14.9973	20.3021	3	0.3166

グループごとに複数項目の集計をしたい

例: パスごとの応答時間の傾向について、複数の条件 (avg, p95, etc...) で集計する

上記のクエリにグルーピングも追加してみます。
以下のようなログからパスでグルーピングして、パスごとのレイテンシ状況を集計します。

{"response_time": 15, "path":"/hoge"}

先ほどからほとんど変わらず、 by キーワードの追加と display の追加で実現できます。

stats count(*) as total,
  avg(response_time) as response_avg,
  pct(response_time, 95) as response_p95,
  sum(response_time >= 1000) as over_1s_count by path
| display path, response_avg, response_p95, over_1s_count, (over_1s_count / total * 100) as over_1s_rate

以下のような結果が得られます。

path	response_avg	response_p95	over_1s_count	over_1s_rate
/hoge	14.9973	20.3021	3	0.3166
/fuga	50.0011	80.3232	12	1.2345

sort コマンドや limit コマンドも利用することでパフォーマンスが悪いパスの一覧を得ることができます。
その他にも以下のような応用も考えられそうです。

• status をグルーピングに追加してパス & status ごとの応答時間傾向を観測する
• status のカウンターを集計項目に追加してパスごとの応答時間傾向 + status 傾向を観測する
• 特定 path で filter した上で bin グルーピングを使って特定 API の時系列での変化状況を観測する
• @logStream でグルーピングしてタスクやインスタンスごとのレイテンシ状況を観測する

おわりに

比較的シンプルな使い方の延長で説明してきましたが、このくらいの知識でも集計クエリを活用できそうなシーンはだいぶ増えるのではないかと思います。

日々の運用で発生するログ調査においても、絞り込みだけでなく集計も活用することでより俯瞰的な調査を行えるようになると思います。
この記事が「クエリよくわかんないしあんまりつかってないなー 」という方などの参考になればと思います。