CloudWatch Logs InsightsでAPIごとの処理時間を集計する方法

集計対象のログ前提

APIごとに以下の情報がログに出ていれば大丈夫です。

項目	説明
リクエストID	リクエスト単位でユニーク
開始・終了	リクエストの開始と終了がわかるログ
メソッド・パス	集計対象の情報

今回の記事でのサンプルログは、👇を想定しています。

# 開始ログ
2099/01/01 00:00:00.000 X-REQUEST-ID-X INFO Request Start POST /api/v1/ho/ge

# 終了ログ
2099/01/01 00:00:00.999 X-REQUEST-ID-X INFO Request End POST /api/v1/ho/ge

※ログに出ている日時が出ていますが、この情報は利用しません。CloudWatchのtimestampを利用します。

遅いAPIの抽出クエリ

CloudWatch Logs Insightsで抽出対象の時間・ロググループを指定して、以下のクエリを実行します。
このクエリで300ms以上かかっているAPIを降順で表示できます。

fields @timestamp, @message
| filter @message like /Request Start|Request End/
| parse @message "* * * * Request * * *" as date, time, requestId, logLevel, logType, method, path
| stats 
    latest(@timestamp) as endTime,
    earliest(@timestamp) as startTime,
    latest(@timestamp) - earliest(@timestamp) as duration
    by requestId, method, path
| filter duration > 300
| sort duration desc
| display fromMillis(endTime) as apiEndTime, requestId, method, path, duration

API単位での集計

次に上記のクエリを発展させて、APIの処理時間の最大・最小・
平均・中央値を計算することで、問題分析で利用可能にします。

fields @timestamp, @message
| filter @message like /Request Start|Request End/
| parse @message "* * * * Request * * *" as date, time, requestId, logLevel, logType, method, path
| stats 
    latest(@timestamp) - earliest(@timestamp) as duration
    by requestId, method, path
| stats 
    max(duration) as maxDuration,
    min(duration) as minDuration,
    avg(duration) as avgDuration,
    pct(duration, 50) as medianDuration,
    count() as requestCount
    by method, path
| sort maxDuration desc
| display maxDuration, minDuration, avgDuration, medianDuration, requestCount, method, path

最後に

開発中にテストしていても、ちょっと遅いだけでは問題で出てこないこともあったので、具体的に数字を把握するために準備しました。

同じような方がいれば、参考になればと思います。