Skip to content

fix(telemetry): binary-search Truncate drop count to avoid O(n) re-renders (#153) - #154

Merged
yaythomas merged 1 commit into
aws:mainfrom
PratikDhanave:fix/telemetry-truncate-binary-search
Nov 3, 2026
Merged

yaythomas merged 1 commit into
aws:mainfrom
PratikDhanave:fix/telemetry-truncate-binary-search

Conversation

@PratikDhanave

Copy link
Copy Markdown
Contributor

Fixes #153.

Problem

telemetry.Truncate drops operation Result fields (step 1) and whole operations (step 2) one at a time, re-rendering the entire record to JSON after every single drop (fits → render). For an invocation with tens of thousands of operations that is O(n) full renders of a multi-megabyte record, inside OnInvocationEnd:

  • A 29,999-operation invocation finished its work in ~22 s, then stalled in truncation to the 900 s Lambda timeout and failed with ExecutionLimitExceeded (the same handler without the plugin succeeds in ~25 s). A CPU profile of a 5,000-operation run showed ~79 % of time in Truncate → fits → json.Marshal.
  • A related consequence: Truncated/DroppedOperations were set after the fits check, so the final record could land a few bytes over the cap — the reported 262,118-byte event exceeded DefaultMaxRecordSizeBytesLog and was cut by CloudWatch Logs so it no longer parsed.

Fix

Dropping more content only shrinks the rendered record, so "fits after dropping the oldest k" is monotonic. Replace both one-at-a-time loops with sort.Search, cutting thousands of renders to O(log n) (~15). Each candidate is sized with the final Truncated/DroppedOperations metadata already applied, so the returned record accounts for those bytes and cannot creep back over the cap.

Drop order (results oldest-first, then whole operations oldest-first, then Input, then Output), the set of retained operations, and all truncation flags are unchanged — this is purely an algorithmic change, no exported API change.

Validation

  • Added telemetry/truncate_dropops_test.go: asserts a 20,000-operation oversized record truncates to fit and the render count stays O(log n) (≤100). On the old code this test does not complete — the one-at-a-time loop renders many thousands of times (locally it exceeds a 2-minute timeout, mirroring the production stall); with the fix it finishes in well under a second.
  • Full go test ./telemetry/... passes; go vet and gofmt clean.

Developed with AI assistance (Claude Code): the root cause from the issue was confirmed, the binary-search fix implemented, and the regression test written and run locally. I reviewed and verified the change and take responsibility for it.

…nders (aws#153)

Truncate dropped operation Results (step 1) and whole operations (step 2) one
at a time, re-rendering the entire record to JSON after every single drop. For
an invocation with tens of thousands of operations that is O(n) full renders of
a multi-megabyte record inside OnInvocationEnd — a 29,999-operation run stalled
to the 900s Lambda timeout and failed with ExecutionLimitExceeded.

Dropping more content only shrinks the rendered record, so the 'fits after
dropping k' predicate is monotonic. Replace both one-at-a-time loops with
sort.Search, reducing thousands of renders to O(log n) (~15). Each candidate is
sized with the final Truncated/DroppedOperations metadata already set, so the
returned record accounts for those bytes and cannot creep back over the cap
(this also fixes the record that landed just over DefaultMaxRecordSizeBytesLog
and was cut by CloudWatch Logs). Drop order, retained operations, and all
truncation flags are unchanged.

Add a regression test asserting the render count stays O(log n) for a
20,000-operation record (the old code renders many thousands of times).
@yaythomas yaythomas added the needs-review Awaiting maintainer review label Nov 3, 2026

@yaythomas yaythomas left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Thanks a bunch @PratikDhanave, welcome to dex! 🙇

This keeps the record within the 262,144-byte cap. The event in the issue is 262,118 bytes, though, which is already under the cap. 262,118 is 262,144 minus the 26 bytes CloudWatch Logs counts per log event. So that is most likely the size the event was cut to. So a record between 262,118 and 262,144 bytes is still cut after this change. Lowering the cap is a separate change, so I'll remove the part about the cut event from the squash commit message.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

2 participants