[Bug]: telemetry truncation time grows with the square of the operation count

未關閉
#908 1 則留言 0 個 reaction 已指派 0 人 在 GitHub 檢視

維護者通常 1 天內回覆

還沒有人認領這個 Issue。

評估

難度
4/5
預估耗時
3-5 天
新手友好度
35/100
Issue 類型
缺陷
描述清晰度
基本清楚
活躍度
活躍
技術堆疊
python

研究方向

Start with truncate_record and fits() in packages/aws-durable-execution-sdk-python-telemetry-exporter/.../truncation.py, in the result and operation phases, and run the reproduction script in the issue to get a baseline time and kept count. Done means the 4,000-operation case finishes far faster while kept and dropped match the current output for the default by-name rendering. The rendering can grow when an older same-name operation is dropped, so a plain binary search is not safe here.

由索引模型根據 Issue 內容生成。

描述

bug pkg:telemetry
Expected Behavior

Truncating an oversized record takes a small share of the invocation, whatever the number of operations.

Actual Behavior

truncate_record calls fits() before it considers each operation, once in the result phase and again in the operation phase. fits() renders the whole candidate record and measures it. So the work grows with the square of the operation count.

With the default LambdaLogExporter (256,000-byte line, operations rendered by name), truncating a record of simple successful steps took 12.8 s for 2,000 operations and 57.8 s for 4,000, on Python 3.14.6.

Every exporter goes through truncate_record when its rendered record is over its limit. Every built-in exporter except FileExporter and HttpExporter sets a default limit, and those two take the same path when a limit is configured.

End to end, with the released packages and aws-durable-execution-sdk-python-testing 1.4.0, a DurableFunctionTestRunner handler that runs 4,000 steps in a row took 7.3 s without the plugin and 82.9 s with it. For 2,000 steps it took 3.1 s and 18.5 s. The plugin run used a LambdaLogExporter subclass that only replaces export() with a no-op. This removes log output, but the comparison still includes the plugin's other work. Truncating a 4,000-operation record alone takes 57.8 s, so truncation is most of the difference.

The time is spent before the invocation returns:

  • on_invocation_end builds the final record and asks the export worker to drain. _ExportScheduler.drain waits on a condition with no timeout.
  • The export worker truncates each record before it exports it.
  • The SDK returns the invocation output only after on_invocation_end returns.
  • The final record also includes operations from earlier invocations. With the default settings it lists every named top-level operation of the execution. So a long execution truncates its accumulated operations when it ends.
  • With EmitMode.ON_CHANGE, the plugin also exports records during the invocation, and the export worker truncates each of them.

The service allows 30,000 operations per execution. Extending the measured growth from 4,000 operations projects about 54 minutes at 30,000 on this test machine. The maximum Lambda timeout is 15 minutes. I did not run 30,000 operations in Lambda. So the invocation that ends an execution of that size is at risk of timing out.

Steps to Reproduce

Run this with aws-durable-execution-sdk-python-telemetry-exporter 1.0.0:

import datetime
import time

from aws_durable_execution_sdk_python_telemetry_exporter.exporters import LambdaLogExporter
from aws_durable_execution_sdk_python_telemetry_exporter.truncation import truncate_record

# The default exporter: 256,000-byte line, operations rendered by name.
exporter = LambdaLogExporter()

start = datetime.datetime(2026, 10, 28, tzinfo=datetime.UTC)


def ts(ms: int) -> str:
    t = start + datetime.timedelta(milliseconds=ms)
    return t.isoformat(timespec="milliseconds").replace("+00:00", "Z")


operations = [
    {
        "id": f"op-{i}",
        "name": f"step-{i}",
        "type": "STEP",
        "subType": "Step",
        "status": "SUCCEEDED",
        "startTime": ts(i * 10),
        "endTime": ts(i * 10 + 3),
        "durationMs": 3,
        "attempt": 1,
    }
    for i in range(4000)
]
record = {
    "recordType": "DurableExecutionTelemetry",
    "schemaVersion": "1.0",
    "executionArn": "arn:aws:lambda:us-east-1:123456789012:function:demo:$LATEST/durable-execution/run-1/inv-1",
    "status": "SUCCEEDED",
    "operations": operations,
}

t0 = time.perf_counter()
out = truncate_record(record, exporter.max_record_size_bytes, exporter.render, exporter.measure)
print(f"truncate_record: {time.perf_counter() - t0:.1f} s")
print(f"kept {len(out['operations'])} operations, dropped {out['droppedOperations']}")

On Python 3.14 it prints a time of about 60 s and kept 1352 operations, dropped 2648.

SDK Version

aws-durable-execution-sdk-python-telemetry-exporter 1.0.0 with aws-durable-execution-sdk-python 3.0.1. main has the same code.

Python Version

3.14

Is this a regression?

No

Additional Context

Two changes would remove most of the cost. Neither changes the public API or the record format.

  1. Measure once after the error causes are removed. Then, in the result phase, measure again only after an operation loses its result. With the default content settings no operation has a result. So today that phase renders the full record once per operation and drops nothing, which is 4,000 renders for the record above.
  2. For the built-in renderings, skip checks that cannot succeed, as the Java SDK's Truncation.truncateMeasured does. After each measurement it adds up an upper bound of how much each drop can shrink the record. It measures again only when that bound could bring the record under the limit. For a rendering that the bound covers, it returns the same record as checking after every drop. The both format holds the operations array and the derived operationsByName map, so its bound must cover the shrink of both. A custom render or measure keeps exact checks. On JDK 21, Java's bounded path truncates a 30,000-operation record in 0.6 s.

The Go SDK had the same problem (Go SDK #153: Truncate re-renders the whole record per dropped operation) and fixed it with a binary search over the drop count (Go SDK PR #154: binary-search the Truncate drop count). A plain binary search that treats fits as monotonic is not guaranteed to find the smallest fitting drop count for the by-name rendering, because dropping an operation can make that rendering larger. When two operations share a name and the newer one failed, dropping the older one makes the summary show the newer one's error. In a check, that grew the rendering from 263 to 2,344 bytes.

Code at the commit I read:

主要語言
Python
星號
58
分支
32
平均合併
1 天 6 小時
30 天內合併 PR
80

環境準備

從這裡開始

  1. 先讀完整個 Issue,再讀專案的貢獻指南。
  2. 在 Issue 下留言說明你要接手 —— 這能避免兩個人做同樣的事。
  3. Fork 儲存庫,在一個分支上完成修改。
  4. 送出 Pull Request,並在描述裡引用這個 Issue 編號。

aws/aws-durable-execution-sdk-python 的其他 Issue

查看 aws/aws-durable-execution-sdk-python 的全部 Issue

相似的 Issue

更多 Python Issue

把新 issue 寄到你的電子郵件信箱

精選適合新手參與的 GitHub issue 摘要。