「発生時刻」と「取り込み時刻」

CloudWatch Logsのログイベントには以下の２つの時刻が含まれます。

① ログの発生時刻 = timestamp
② ログの取り込み時刻 = ingestionTime

ログが発生(①)してから、実際にCloudWatchLogsに取り込まれるまで(②)時間差があります。

イメージ

(例) ログをCloudWatchエージェントでCloudWatch Logsに送る場合

詳細

CloudWatchLogsへのログイベント送信は、統合されたサービスやCloudWatchエージェントを使っていれば意識することは少ないですが、PutLogEventsするとき発生時刻をInputLogEventのtimestampで指定しています。この送信したイベントを、受信側のCloudWatchLogsが取り込んだ時刻がingestionTimeです。

今回やること

「timestamp」と「ingestionTime」の時間差を可視化し観察してみます。
Logs Insightsでログデータから両方取得できるのでstats機能を使って集計します。

その時間差に「Lambda」「EC2+CloudWatchエージェント」「API Gateway」で傾向に違いがあるかも見ていきます。

1. 時間差を可視化

1-1. 取り込み時刻を表示してみる

Logs Insightsの初期クエリではtimestampしか表示しませんが、ingestionTimeも表示してみます

クエリ

fields @timestamp, @ingestionTime, @message, @logStream, @log
| sort @timestamp desc
| limit 20

結果

Logs Insights上はtimestampはJST、ingestionTimeはUTCで表示されるのでややこしいですが9秒程度取り込みまでに差があるのがわかります。

1-2. 時間差を表示してみる

クエリ

fields @timestamp, @ingestionTime, toMillis(@ingestionTime) - toMillis(@timestamp) as diff
| sort @timestamp desc
| limit 20

結果

toMillis(@ingestionTime) - toMillis(@timestamp) as diff

toMillisでタイムスタンプをミリ秒に変換し、差分の時間をdiffという名前のフィールドに表示できました。

1-3. 時間差をstatsで可視化してみる

クエリ

fields @timestamp, @ingestionTime, toMillis(@ingestionTime) - toMillis(@timestamp) as diff
| sort @timestamp desc
| stats max(diff), pct(diff,50), avg(diff) by bin(30min)

30分毎に区切った区間で、diffの最大値、中央値(50パーセンタイル)、平均値を出してみます。
期間は２週間を指定してみました。Logs Insightsで出力できるログフィールドは最大1,000なので収まるように粒度と期間を調整しています。

結果(可視化タブ)

statsを使うことで「可視化タブ」にグラフ表示できました。

2. 時間差を比較してみる

ログ送信元によって時間差が違うのか、それぞれログループを指定して前述のクエリをかけて見ていきます。
手元のログで限られた期間しか見ていないので、状況によって傾向が異なる可能性があります。ご了承ください。

2-1. Lambda

LambdaはCloudWatchと統合されているので適切な権限をつければ自動でログ出力してくれるので、そのグループに対しクエリをかけます。(/aws/lambda/{function名})

中央値は9秒弱といったところでしょうか。

2-2. EC2 + CloudWatchエージェント

EC2がCloudWatchエージェント経由で出力しているロググループに対してクエリをかけます。

中央値が5秒強ですが、最大値は16秒付近。
このあたりはエージェント設定ファイルの内容(force_flush_intervalあたり?）によっても変わるかもしれないですね。

2-3. API Gateway

API Gatewayでログ出力を有効にすると出力されるロググループに対してクエリをかけます。
(API-Gateway-Execution-Logs_{ステージID})

中央値が20秒強と、今回見比べた中では一番長いです。

終わりに

サービスによって取り込みまでのタイムラグに違いがありましたが、要因を推測してみるのも楽しそうですね。

今回Logs Insightsを使って可視化しましtが、改めて手軽で便利だな〜と感じました。

個人的な動機として、開発・運用しているサービスの中に「アラート発生時に自動で"CloudWatch Logsから関連ログを収集し、チケットに追記する処理"」というものがあり、ingestionTimeを意識することがあったので、今回の結果は参考になりました。

では、また。

参考