Visualize CloudWatch Logs ingestion lag with Logs Insights
Tags: aws, cloudwatchlogs, cloudwatchlogsinsights
Published: 2023-06-25 18:35:14

I have visualized the lag time it takes to ingest logs to CloudWatch Logs and compared it by source service!

#0. "timestamp" and "ingestionTime"
CloudWatch Logs event includes the following two times.

- (i) [timestamp](https://docs.aws.amazon.com/ja_jp/AmazonCloudWatchLogs/latest/APIReference/API_OutputLogEvent.html#CWL-Type- OutputLogEvent-timestamp) = The time the event occurred  
- (ii) [ingestionTime](https://docs.aws.amazon.com/ja_jp/AmazonCloudWatchLogs/latest/APIReference/API_OutputLogEvent.html#CWL -Type-OutputLogEvent-ingestionTime) =The time the event was ingested into CloudWatch Logs

There is a lag between "timestamp" and "ingestionTime".

![sequence](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/4ghvjpxv0eujqgpkjlbq.png)

The "timestamp" (=event occurrence time) is passed by the parameter [InputLogEvent](https://docs.aws.amazon.com/AmazonCloudWatchLogs/latest/APIReference/API_InputLogEvent.html) of [PutLogEvents](https://docs.aws.amazon.com/AmazonCloudWatchLogs/latest/APIReference/API_PutLogEvents.html).
This is something we're rarely aware of if we're using an integrated service or CloudWatch agent


# 1. Visualize CloudWatch Logs ingestion lag

We can get both from the log data in Logs Insights, so we will aggregate them using the [stats command](https://docs.aws.amazon.com/AmazonCloudWatch/latest/logs/CWL_QuerySyntax-Stats.html).

## 1-1. Query the "timestamp" and "ingestionTime"

The initial query of Logs Insights only displays **timestamp**, but let's display **ingestionTime** as well

```scheme
fields @timestamp, @ingestionTime, @message, @logStream, @log
| sort @timestamp desc
```

#### Result


![logs](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/uaokfkg8jwurog87q229.png)

You can see that there is a time lag of several seconds.


## 1-2. Query the time difference(=lag)

```scheme
fields @timestamp, @ingestionTime, toMillis(@ingestionTime) - toMillis(@timestamp) as diff
| sort @timestamp desc
```
#### Result
![logs](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/eax2ksv73s9jzicmv6rl.png)

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

["toMillis" function](https://docs.aws.amazon.com/AmazonCloudWatch/latest/logs/CWL_QuerySyntax-datetime.html) converts the timestamp found in the named field into a number representing the milliseconds.

## 1-3. Visualize the time difference(=lag) with stats

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

The maximum, median (50th percentile), and mean of the difference are output at 30-minute intervals. The period is specified as 2 weeks.
The maximum number of log fields that Logs Insights can output is 1,000, so the interval and period must be adjusted accordingly.

### Results

![visualization](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/h7fcetd8eiqc9l80y9pc.png)

# 2 Comparison of lag by source service
Let's run a visualization query to see if the time difference differs depending on the log source!

## 2-1. AWS Lambda

AWS Lambda is integrated with CloudWatch and automatically outputs logs with appropriate permissions, so we query the group. (/aws/lambda/{function name})


![aws lambda](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/2iydsfoiqof0srkuj49a.png)
The median time is about less than 9 seconds.

## 2-2. EC2 + CloudWatch Agent
Query the log group that EC2 is outputting via CloudWatch Agent.

![ec2](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/vgbjtc50x0h737w4be8v.png)

The median is a little over 5 seconds, but the maximum is around 16 seconds.
It may depend on the contents of the agent configuration file (per force_flush_interval?) 

## 2-3. API Gateway
Query the log group that is output when log output is enabled on API Gateway.
(API-Gateway-Execution-Logs_{stage ID})

![api gateway](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/ny6vm2qrv5hbobb38qvn.png)

The median time is over 20 seconds, the longest among those compared.

# Conclusion

There were differences in lagging tendencies among the services. It would be fun to try to guess the cause.

I used Logs Insights to visualize the data, and found it easy and useful.

This post is an English rewrite of [an post I wrote in Japanese](https://iret.media/71989).