Skip to content

Reduce requests necessary for lambda log publishing to cloudwatch logs #10234

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 1 commit into from
Feb 20, 2024

Conversation

dfangl
Copy link
Member

@dfangl dfangl commented Feb 13, 2024

Motivation

We currently make 3 requests to CloudWatch logs for every lambda invocation:

  1. CreateLogGroup (will fail for all but the first invoke for that function)
  2. CreateLogStream (will fail for all but the first invoke for that execution environment)
  3. PutLogEvents

We can drastically reduce the calls, and also load on the gateway, if we only execute the first two calls if PutLogEvents fails.
If it fails, it equals to 4 calls (failed PutLogEvents, then CreateLogGroup, then CreateLogStream), but then only one call for every invocation (for the same environment) afterwards.

Compared to 3 calls for every single invocation right now. There is also a lot of logic in store_cloudwatch_logs which is not necessary anymore with the new lambda provider.

Changes

  • Change logic to ask for forgiveness instead of permission for log group creation
  • All events for a single invocation will now have the same timestamp. At some point we should pass the timestamps from the init to the logs endpoint correctly.

@dfangl dfangl added the semver: patch Non-breaking changes which can be included in patch releases label Feb 13, 2024
@coveralls
Copy link

Coverage Status

coverage: 83.828% (+0.002%) from 83.826%
when pulling 5f81c0d on lambda-logging-efficiency
into 3cce93c on master.

Copy link

LocalStack Community integration with Pro

    2 files  ±0      2 suites  ±0   1h 22m 41s ⏱️ -29s
2 635 tests ±0  2 388 ✅ ±0  247 💤 ±0  0 ❌ ±0 
2 637 runs  ±0  2 388 ✅ ±0  249 💤 ±0  0 ❌ ±0 

Results for commit 5f81c0d. ± Comparison against base commit 3cce93c.

Copy link
Member

@joe4dev joe4dev left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

My only question mark is related to the behavior change that could potentially affect the logging order. If these logs get retrieved from CloudWatch with order_by timestamp 😬

Otherwise, LGTM 👍

logs = log_item.logs.splitlines()
# until we have a better way to have timestamps, log events have the same time for a single invocation
log_events = [
{"timestamp": int(time.time() * 1000), "message": log_line} for log_line in logs
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Could that behavioral change mess up the log order in CloudWatch?
Compared to the previous heuristic:

simple heuristic: assume log lines were emitted in regular intervals

another reason to tackle structured logging and improved logging soon ...

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We will probably be fine, as it should not get reordered based on the timestamp in our codebase. Definitely something to look out for, and fix as soon as possible.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

😬 🤞

Not in our Python code, but it could happen when querying from sqlite with CloudWatch v2 🤷
For example in localstack/services/cloudwatch/cloudwatch_database_helper.py, if we ScanBy.TimestampDescending 🙈

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I could increase it in 1ms intervals to be sure :)

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

But reordering Events with the same timestamp would be a parity violation anyway, so not sure how much sense it makes.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yeah, but we never had this parity
the closest we have to parity is event ordering (through some random heuristic)

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

guess it doesn't matter too much if we fix it soonish 🔮

@dfangl dfangl added this to the 3.2 milestone Feb 19, 2024
@dfangl dfangl merged commit b387bfb into master Feb 20, 2024
@dfangl dfangl deleted the lambda-logging-efficiency branch February 20, 2024 15:25
dfangl added a commit that referenced this pull request Feb 21, 2024
dfangl added a commit that referenced this pull request Feb 21, 2024
dfangl added a commit that referenced this pull request Apr 2, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
semver: patch Non-breaking changes which can be included in patch releases
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants