CloudWatch Logsの ”取り込み時間差" をLogs Insightsで可視化しサービス別に比較してみた


# 「発生時刻」と「取り込み時刻」
CloudWatch Logsのログイベントには以下の２つの時刻が含まれます。
- ① ログの発生時刻 = [timestamp](https://docs.aws.amazon.com/ja_jp/AmazonCloudWatchLogs/latest/APIReference/API_OutputLogEvent.html#CWL-Type-OutputLogEvent-timestamp)
- ② ログの取り込み時刻 = [ingestionTime](https://docs.aws.amazon.com/ja_jp/AmazonCloudWatchLogs/latest/APIReference/API_OutputLogEvent.html#CWL-Type-OutputLogEvent-ingestionTime)


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

## イメージ
(例) ログをCloudWatchエージェントでCloudWatch Logsに送る場合
```mermaid
sequenceDiagram
  participant S as システム
  participant L as ログファイル & CloudWatchエージェント
  participant C as CloudWatch Logs
  S->>S: ログ発生 (①timestamp記録)
  S-)L: 書き込み
  L-)C: PutLogEvents
  C-)C: ログの取り込み (②ingestionTime)
```

## 詳細
CloudWatchLogsへのログイベント送信は、統合されたサービスやCloudWatchエージェントを使っていれば意識することは少ないですが、[PutLogEvents](https://docs.aws.amazon.com/ja_jp/AmazonCloudWatchLogs/latest/APIReference/API_PutLogEvents.html)するとき発生時刻を[InputLogEvent](https://docs.aws.amazon.com/ja_jp/AmazonCloudWatchLogs/latest/APIReference/API_InputLogEvent.html)の**timestamp**で指定しています。この送信したイベントを、受信側のCloudWatchLogsが取り込んだ時刻が**ingestionTime**です。



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

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

# 1. 時間差を可視化

## 1-1. 取り込み時刻を表示してみる
Logs Insightsの初期クエリでは**timestamp**しか表示しませんが、**ingestionTime**も表示してみます

```scheme:クエリ
fields @timestamp, @ingestionTime, @message, @logStream, @log
| sort @timestamp desc
| limit 20
```
#### 結果
![CloudWatch_Management_Console.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/43631/0b9abe5b-e2a8-6978-c42a-eba32853f65d.png)
Logs Insights上は**timestamp**はJST、**ingestionTime**はUTCで表示されるのでややこしいですが9秒程度取り込みまでに差があるのがわかります。

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

```scheme:クエリ
fields @timestamp, @ingestionTime, toMillis(@ingestionTime) - toMillis(@timestamp) as diff
| sort @timestamp desc
| limit 20
```



#### 結果
![スクリーンショット 2023-03-24 4.39.56.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/43631/4823e18c-3056-0671-b5b4-32b5aacc3915.png)

> 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を使うことで「可視化タブ」にグラフ表示できました。
![スクリーンショット 2023-03-24 5.04.35.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/43631/3606372f-3c3d-da6d-6a04-6c1b0ab2c544.png)



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

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

## 2-1. Lambda

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

![スクリーンショット 2023-03-24 5.12.11.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/43631/aa5d4296-5787-cc07-e6af-3814594d2ce6.png)

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

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

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

![スクリーンショット 2023-03-24 5.14.03.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/43631/208e468b-9cf4-cdd8-f0f1-b704025c68ba.png)

中央値が5秒強ですが、最大値は16秒付近。
このあたりは[エージェント設定ファイル](https://docs.aws.amazon.com/ja_jp/AmazonCloudWatch/latest/monitoring/CloudWatch-Agent-Configuration-File-Details.html)の内容(force_flush_intervalあたり?）によっても変わるかもしれないですね。

## 2-3. API Gateway

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

![スクリーンショット 2023-03-24 5.17.19.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/43631/5d7e1a11-39a5-4011-edfb-fe3fedb585a0.png)

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

# 終わりに

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

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

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


では、また。


### 参考

- [CloudWatch Logs Insights を使用したログデータの分析](https://docs.aws.amazon.com/ja_jp/AmazonCloudWatch/latest/logs/AnalyzingLogData.html)
    - [サポートされるログと検出されるフィールド](https://docs.aws.amazon.com/ja_jp/AmazonCloudWatch/latest/logs/CWL_AnalyzeLogData-discoverable-fields.html)
    - [クエリ構文](https://docs.aws.amazon.com/ja_jp/AmazonCloudWatch/latest/logs/CWL_QuerySyntax.html)
    - [グラフでのログデータの視覚化](https://docs.aws.amazon.com/ja_jp/AmazonCloudWatch/latest/logs/CWL_Insights-Visualizing-Log-Data.html)


- [CloudWatch Logs アクション](https://docs.aws.amazon.com/ja_jp/AmazonCloudWatchLogs/latest/APIReference/API_Operations.html)
    - [PutLogEvents](https://docs.aws.amazon.com/ja_jp/AmazonCloudWatchLogs/latest/APIReference/API_PutLogEvents.html)
    - [GetLogEvents](https://docs.aws.amazon.com/ja_jp/AmazonCloudWatchLogs/latest/APIReference/API_GetLogEvents.html)
- [CloudWatch Logs データタイプ](https://docs.aws.amazon.com/ja_jp/AmazonCloudWatchLogs/latest/APIReference/API_Types.html)
    - [InputLogEvent](https://docs.aws.amazon.com/ja_jp/AmazonCloudWatchLogs/latest/APIReference/API_InputLogEvent.html)
    - [OutputLogEvent](https://docs.aws.amazon.com/ja_jp/AmazonCloudWatchLogs/latest/APIReference/API_OutputLogEvent.html#CWL-Type-OutputLogEvent-ingestionTime)


- [CloudWatch Logs クォータ](https://docs.aws.amazon.com/ja_jp/AmazonCloudWatch/latest/logs/cloudwatch_limits_cwl.html)

- [AWS DeepRacerの報酬関数トレースログをCloudWatchLogs Insightsでパースして分析](https://qiita.com/shu85t/items/7fdad25d012fc3ac1f4d)