CloudWatchLogs Insightsでいろいろ分析っぽいことをしてみよう

本記事は[公式のドキュメント](https://docs.aws.amazon.com/ja_jp/AmazonCloudWatch/latest/logs/CWL_QuerySyntax.html)を読めばだいたい書き方が分かる内容を自分用にまとめたものになります。
ドキュメントを読み慣れている方はそちらをご参照ください。

# 【前提】CloudWatchLogsに格納されているデータの形式

[LTSV](http://ltsv.org/)形式なのか、単純なTSV形式のログなのかによって表記が変わってきます。
この記事ではLTSV形式のnginxのログを想定して書きます。

LTSVの中身は下記のようにラベル付けしています。

```
log_format ltsv "time:$time_local"
                "\thost:$remote_addr"
                "\tforwardedfor:$http_x_forwarded_for"
                "\treq:$request"
                "\tstatus:$status"
                "\tmethod:$request_method"
                "\turi:$request_uri"
                "\tsize:$body_bytes_sent"
                "\treferer:$http_referer"
                "\tua:$http_user_agent"
                "\treqtime:$request_time"
                "\tcache:$upstream_http_x_cache"
                "\truntime:$upstream_http_x_runtime"
                "\tvhost:$host";
```

これらのラベルの中身は `structural_log` の要素としてアクセスできるという前提になります。
例えば `structural_log.status` とすればサーバが返しているステータスコードを参照できる、というものです。

それを踏まえた上でいろいろ試していきます。

# statsを使ってステータスコードごとにカウントする

```
stats count(*) by structural_log.status
```

```:実行結果
1		341
2	200	236174
3	500	6
4	499	3
5	20	2
6	2	5
7	400	3
```

`stats`は統計用コマンドで`count`関数を使うことで`structural_log.status`ごとのログの数を集計した結果を見ることができます。
`count`以外にも `avg` `sum` `count` `min` `max`などがあります。
ここらへんはSQL書ける人なら違和感なく使うことができるかと思います。
また`pct()`という関数もあり、こちらはパーセンタイルの結果を出すことができます。 `pct(*, 50)`とすれば中央値が簡単に出せてとても便利です。

## `filter`と`sort`を追加で使ってみる

しかし上記のログ、ステータスコードが変なのが多いですね。
そういうときはfilterで不要なデータを除外しましょう。（ログが変な状態になっているということでもあるので、別途なぜこういうログが出ているのか、の調査もちゃんとやりましょう）

```
filter not isempty(structural_log.status)
| filter structural_log.status >= 200
| stats count(*) by structural_log.status
| sort structural_log.status
```

```:実行結果
1	200	236174
2	400	2
3	499	3
4	500	6
```

`isempty`関数は該当の項目が、欠落しているか、空の文字列かの場合にtrueを返します。
ここでは空のケースを除外したいので`not`演算子を使うことで`structural_log.status`がある状態だけに限定するようにしています。
似たような関数で`isblank`関数もあります。そちらは空文字列を含む場合もtrueを返すようになるみたいなので状況に応じてそちらを使うのもいいでしょう。

そしてそのフィルタを掛けたあとで`>=`演算子でステータスコードが200以上のものに絞ってます。
今回のケースではこちらのフィルタだけあれば十分なのですが、`isempty`は紹介をしたいがために使った節があります。あと、filterは複数使うことができるんだよ、ということの紹介のためにも入れました。

ついでに`structural_log.status`の昇順で並び替えるように`sort`コマンドもつけておきました。

これにより少ないながらもエラーが出ていて、どれほどの件数が出ているかが可視化できます。
件数が少なければ事業インパクトは少なく対応を後回しにするなんて選択肢も出てきますね。

### :warning: `isblank` `isempty` には不具合があります

上記のような書き方をしていましたが、稀に `結果なし` というレスポンスを返すことがありました。
`isblank` だと平気で `isempty` ではダメ、その逆もまた然り。
しかし`isblank` と `isempty` それぞれ単体で下記のように実行した結果が同値になることは確認済みです。

```:isemptyとisblankの差分検証
display isblank(structural_log.reqtime), isempty(structural_log.reqtime)
```

これはどういうことだろう？とAWSのサポートに問合せたところ

1. `filter not(isblank(structural_log.status))` のように `filter not` に直接 `isblank` や `isempty` の結果を使うと意図しない挙動をすることがある
2. `isblank` において `isblank(structural_log.status) | filter structural_log.status >= 200` のように `isblank` で使った項目を、後に比較演算子で利用すると空白文字列(" ")が除外されない

とのことでした。
今回自分は1の方を引き当てていました。まさか自分がバグを引き当てるとは…。
後者については1の調査の過程でAWS側が見つけてくれたものです。

前者について回避する場合は一旦別名にすることで回避できるそうです。

```
fields isempty(structural_log.status) as isEmpty # isEmptyという名前でisempty()の結果を保存
| filter not isEmpty # それを元にnotでfilterする
| filter structural_log.status >= 200
| stats count(*) by structural_log.status
| sort structural_log.status
```

もし「結果なし」になった場合はお試しください。

これは2021年2月17日現在でのAWSからの報告です。
上記のような使い方をする際はお気をつけください！

# `parse()` コマンドや`pct()` 関数を使ってAPIごとの統計をとってみる

Insightsを使わずとも、各種サーバの計測は皆様やっているかと思います。
普段はそちらを使えば問題なし、ですがそうじゃないケースもあると思います。
例えば計測が部分的にできていなかったり、特定のパターンのときだけを集計してみたい、とか。

そういう場合はInsightsでサクッと試してみましょう。

```
parse structural_log.uri "/*/*" as first_path, other
| stats pct(structural_log.reqtime, 99) as pct99, count(first_path) by first_path
| sort pct99 desc
```

```:実行結果
1	API_F	2.4243	1865
2	API_A	2.1297	21591
3	API_C	1.6649	99
4	API_B	1.613	12624
5	API_E	1.6125	125
6	API_D	1.209	51
```

`parse`コマンドを使うと正規表現でログの中身をキャプチャすることができます。
`structural_log.uri`の中身はリクエストされたURIのパス以降の部分が含まれています。
つまり`/path/path2/?query=hoge&fuga`のような文字列です。
ここでは`path`部分と`path2/?query=hoge&fuga`部分をキャプチャしてそれぞれ`first_path`と`other`という名前をつけています。
正規表現をもう少し工夫すればいい感じのキャプチャができますが、まぁここはサンプルということでよろしくお願いします。

そして、その `first_path` ごとのレスポンス速度を９９パーセンタイルで統計を取ります。
さらに `pct` の結果に対して `as` を使いエイリアスをつけることで `sort` のキーとして採用することができます。
また合わせて `count(first_path)` を指定することで `first_path` ごとのリクエスト回数もいっぺんに取得することができます。

この例ではAPI_Fが一番遅く、レスポンスを返すのに2.4秒ほどかかっているということがわかります。
もしこのAPI_Fが頻繁に使われるAPIなのであればリファクタリングなどで改善をしたときに効果が高い…と言えますが
同時に取得しているcountによって一番効果が高そうなのはAPI_Aかもしれないぞ？と見ることができます。

もちろん、`parse`する前に`filter`を挟むことで特定のパターン（例えばAPI_A, B, Cだけに絞っておくとか）にも対応できるでしょう。

## 小技ですが `count() by` に論理値（比較演算子）も使える

レスポンスを返すのに3秒以上かかったかリクエストがどのパスにどれだけあったかを集計をする、というクエリを書くとこんな感じです。

```
filter not isblank(structural_log.reqtime)
| parse structural_log.uri "/*/*" as first_path, other
| stats count(*) by structural_log.reqtime > 3, first_path
```

```
1	1	API_C	58
2	0	API_A	37
3	0	API_B	33
4	0	API_C	5
```

`structural_log.reqtime > 3` のところ（2列め）が0となっていれば3秒以下でレスポンスを返せていて、1となっていれば3秒以上かかっています。
これを見るとAPI_Cのリクエストのほとんどが3秒以上かかっていて匂うAPIだと言えそうですね…。とかが分かります。


# 障害が起きていたと思われる時間を `bin()` で出してみる

サーバが500を返していた、というログが残っていれば、それがどの時間帯にどれだけ出ていたかを見れると嬉しいですよね。
そういうときは `bin()` を使うと便利です。
`bin()` はCloudWatch側で付与してくれる `@timestamp` を切り上げ、つまり丸め処理をしてくれます。
引数として丸める単位を指定できます。
例えば1分単位で集計したい場合は下記のように `bin(1m)` とすればOKです。

```
filter structural_log.status in [200, 499, 500, 503]
| stats count(*) by bin(1m) as time, structural_log.status
| sort time
```

```:実行結果
1	2021-02-17T20:46:30.000+09:00	200	33750
2	2021-02-17T20:47:00.000+09:00	200	162285
3	2021-02-17T20:47:00.000+09:00	500	5
```

しれっと `in []` を使って集合要素に対してフィルターを掛けているあたりも便利ですね。
またもっと粒度を細かく、という場合には `bin(30s)` （30秒単位）も可能です。


# シンプルにエラーを特定したいとき
```
filter structural_log.status >= 499
| display structural_log.status, structural_log.uri, @logStream
```

```:実行結果
1	500	API_A	log-group-name
2	500	API_C	log-group-name
3	500	API_B	log-group-name
4	500	API_E	log-group-name
5	503	API_D	log-group-name
```

上記のようにステータスコードを499以上で絞りこみます。
その後に、ステータスコードと、エラーの起きたリクエストのURI、そして `@logStream` を表示するようにします。
ステータスコードとURIを見れば、どこのURIでエラーが起きているかがすぐに分かります。
そして `@logStream` (実行結果の `log-group-name` のところ) はInsightsから提供されるフィールドで、CloudWatchLogsの該当のログのところへのリンクを表示してくれます。クリックして開いた先の1,2行上を見ればだいたいbacktraceが出ているので、「どこで」に加えて「何が起きた」までサッと特定することができます。
当たり前の話ですがエラーログの内容が充実していないと「何が起きた」の特定に至らないこともありますが…とはいえ膨大なログの中から原因のログが特定できるだけでも手助けになるかな、と思います。


# 結びに

CloudWatchLogs Insightsは、サッと何かを見たいときに強力なツールとして（自分の中で）活躍してくれています。
ただ、まだ集計方法が自分の中で定着しておらず、いつも思い出しながらクエリを書いています。
本記事はそんな自分と、これからInsightsを触ってみようという方の助けになればと思います。

※CloudWatchInsightsはスキャンしたログの量に応じて課金されるので数カ月分、みたいな膨大な量の集計はしないようにお気をつけください。