CloudWatch Logs Insights 集計クエリ入門

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

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

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

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

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

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

```json
{"status": 200}
```

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

```sql
stats count(*) by status
```

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

| status | count(\*) |
| ------ | --------- |
| 200    | 15        |
| 400    | 3         |

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

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

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

```sql
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 であること__を利用することで、以下のように表現できます。
後述しますが、このテクニックは複数の集計値を扱う場合に有用になってきます。

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

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

```sql
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)` と正味同じ挙動を実現できます。

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


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

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

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

```sql
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 にする

```sql
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` キーワードの手前の集計値を増やすことで、複数の集計項目を取り扱うことができます。

```json
{"response_time": 15}
```

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

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

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

```sql
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-をせずに条件付きのカウントをしたい)を利用しています。
仮に `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...) で集計する__

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

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

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

```sql
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` でグルーピングして__タスクやインスタンスごとのレイテンシ状況__を観測する

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

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