本記事は公式のドキュメントを読めばだいたい書き方が分かる内容を自分用にまとめたものになります。
ドキュメントを読み慣れている方はそちらをご参照ください。
【前提】CloudWatchLogsに格納されているデータの形式
LTSV形式なのか、単純な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コマンドもつけておきました。
これにより少ないながらもエラーが出ていて、どれほどの件数が出ているかが可視化できます。
件数が少なければ事業インパクトは少なく対応を後回しにするなんて選択肢も出てきますね。
isblank isempty には不具合があります
上記のような書き方をしていましたが、稀に 結果なし というレスポンスを返すことがありました。
isblank だと平気で isempty ではダメ、その逆もまた然り。
しかしisblank と isempty それぞれ単体で下記のように実行した結果が同値になることは確認済みです。
display isblank(structural_log.reqtime), isempty(structural_log.reqtime)
これはどういうことだろう？とAWSのサポートに問合せたところ
-
filter not(isblank(structural_log.status))のようにfilter notに直接isblankやisemptyの結果を使うと意図しない挙動をすることがある -
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はスキャンしたログの量に応じて課金されるので数カ月分、みたいな膨大な量の集計はしないようにお気をつけください。