Skip to content

Commit 5c64ef4

Browse files
author
Alex Wang
committed
fix(insight): keep one pending export snapshot per execution
The export scheduler held a single pending slot for the whole plugin. When two executions were in flight on one plugin instance, execution B's RUNNING snapshot could replace execution A's SUCCEEDED snapshot before the worker claimed it. A's drain() then returned once B's record was flushed, and A's terminal record was never exported. Lambda runs one invocation per environment, but the local test runner and the conformance suite drive independent executions concurrently through one shared plugin, where this lost 30-37% of terminal records in a two-thread probe. Key the pending map by executionArn. A snapshot only replaces its own execution's entry, the worker exports entries in first-arrival order, and a flush request is honored only once every pending record is exported, so drain() means everything scheduled by any execution has been delivered. A RUNNING snapshot never replaces a pending terminal snapshot for the same execution. Close the execution state in on_invocation_end before emitting and draining. An operation-change hook from a checkpoint completing during the drain, or arriving after the state was discarded, is dropped instead of recreating state and emitting a trailing RUNNING record. When the worker thread cannot be started, drain() now exports pending records inline on the calling thread instead of disabling export for the plugin's lifetime and dropping the record.
1 parent 8742ad9 commit 5c64ef4

5 files changed

Lines changed: 354 additions & 67 deletions

File tree

packages/aws-durable-execution-sdk-python-insight/README.md

Lines changed: 8 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -57,10 +57,14 @@ Behavior is validated cross-SDK by the `insight` conformance suite
5757

5858
> **Note (asynchronous export).** Export rendering, truncation, `export()`, and
5959
> `flush()` run on one lazy background worker per plugin. Checkpoint hooks only
60-
> replace the latest pending snapshot and wake the worker. Consecutive
61-
> `on-change` snapshots may coalesce while an export is in flight. An invocation
62-
> that emits a record drains the latest snapshot and flushes exporters before it
63-
> returns; invocations that emit nothing do not start or flush the worker.
60+
> replace the latest pending snapshot **for their own execution** and wake the
61+
> worker; executions in flight at the same time (as under the local test runner)
62+
> never displace each other's snapshots, and a terminal snapshot is never
63+
> replaced by a later `RUNNING` one. Consecutive `on-change` snapshots of one
64+
> execution may coalesce while an export is in flight. An invocation that emits
65+
> a record drains every pending snapshot and flushes exporters before it
66+
> returns; invocations that emit nothing do not start or flush the worker. If
67+
> the worker thread cannot be started, that drain exports inline instead.
6468
6569
## Requirements
6670

Lines changed: 105 additions & 56 deletions
Original file line numberDiff line numberDiff line change
@@ -1,7 +1,17 @@
11
# SPDX-FileCopyrightText: 2026-present Amazon.com, Inc. or its affiliates.
22
#
33
# SPDX-License-Identifier: Apache-2.0
4-
"""Latest-pending asynchronous export scheduling for Workflow Insight."""
4+
"""Latest-pending asynchronous export scheduling for Workflow Insight.
5+
6+
One pending slot is kept **per execution** (keyed by ``executionArn``). Each
7+
record is a complete snapshot of its execution, so a newer snapshot for the same
8+
execution supersedes an older one that has not been exported yet, while records
9+
for different executions never displace each other. The plugin already tracks
10+
state per execution, and the local test runner drives independent executions
11+
concurrently through one shared plugin instance, so a single plugin-wide slot
12+
would silently drop one execution's terminal record whenever another execution
13+
scheduled a snapshot first.
14+
"""
515

616
from __future__ import annotations
717

@@ -15,70 +25,81 @@
1525

1626
_logger = logging.getLogger("aws_durable_execution_sdk_python_insight")
1727

28+
_TERMINAL_STATUSES = frozenset({"SUCCEEDED", "FAILED"})
29+
30+
31+
def _is_terminal(record: dict[str, Any]) -> bool:
32+
return record.get("status") in _TERMINAL_STATUSES
33+
1834

1935
class _ExportScheduler:
20-
"""Run all exporters on one lazy worker with one latest pending record."""
36+
"""Run all exporters on one lazy worker with one pending record per execution."""
2137

2238
def __init__(self, exporters: list[InsightExporter]) -> None:
2339
self._exporters = exporters
2440
self._condition = threading.Condition(threading.Lock())
25-
self._pending: dict[str, Any] | None = None
41+
# executionArn -> latest pending snapshot for that execution. Insertion
42+
# ordered, so the worker exports executions in first-arrival order;
43+
# replacing an entry keeps its position.
44+
self._pending: dict[str, dict[str, Any]] = {}
2645
self._flush_requested = False
2746
self._flush_event: threading.Event | None = None
2847
self._worker: threading.Thread | None = None
29-
self._disabled = False
48+
self._start_failure_logged = False
3049

3150
def schedule(self, record: dict[str, Any]) -> None:
32-
"""Replace the pending snapshot and return without running exporters."""
51+
"""Replace this execution's pending snapshot and return without exporting."""
52+
key = str(record.get("executionArn", ""))
3353
displaced: dict[str, Any] | None = None
34-
failed_pending: dict[str, Any] | None = None
3554
start_error: Exception | None = None
3655
with self._condition:
37-
if self._disabled:
56+
displaced = self._pending.get(key)
57+
# A terminal snapshot is final. A RUNNING snapshot for the same
58+
# execution that arrives after it (an operation-change hook from a
59+
# checkpoint completing during the end-of-invocation drain) must not
60+
# replace it, or the execution would be reported as still running.
61+
if (
62+
displaced is not None
63+
and _is_terminal(displaced)
64+
and not _is_terminal(record)
65+
):
3866
return
39-
displaced = self._pending
40-
self._pending = record
41-
failed_pending, start_error = self._ensure_worker_locked()
67+
self._pending[key] = record
68+
start_error = self._ensure_worker_locked()
4269
self._condition.notify()
43-
# Releasing either record may run custom finalizers, so do it unlocked.
44-
del displaced, failed_pending
45-
if start_error is not None:
46-
_logger.warning(
47-
"workflow-insight: could not start export worker; disabling "
48-
"asynchronous export: %s",
49-
start_error,
50-
)
70+
# Releasing the displaced record may run custom finalizers, so do it unlocked.
71+
del displaced
72+
self._log_start_failure(start_error)
5173

5274
def drain(self) -> None:
53-
"""Wait until the latest pending record is exported and exporters flush."""
54-
failed_pending: dict[str, Any] | None = None
75+
"""Wait until every pending record is exported and exporters flush.
76+
77+
Records scheduled by any execution are exported before the flush, so a
78+
drain issued at one execution's invocation end also delivers snapshots
79+
that a concurrently running execution scheduled earlier.
80+
"""
5581
start_error: Exception | None = None
5682
with self._condition:
57-
if self._disabled:
58-
return
5983
if not self._flush_requested:
6084
self._flush_requested = True
6185
self._flush_event = threading.Event()
6286
flush_event = self._flush_event
6387
assert flush_event is not None
64-
failed_pending, start_error = self._ensure_worker_locked()
65-
started = not self._disabled
88+
start_error = self._ensure_worker_locked()
89+
worker_running = self._worker is not None
6690
self._condition.notify()
67-
del failed_pending
68-
if start_error is not None:
69-
_logger.warning(
70-
"workflow-insight: could not start export worker; disabling "
71-
"asynchronous export: %s",
72-
start_error,
73-
)
74-
if started:
91+
self._log_start_failure(start_error)
92+
if worker_running:
7593
flush_event.wait()
94+
return
95+
# No worker could be started. Export and flush on the calling thread so
96+
# nothing scheduled is dropped; this is the invocation-end path, which
97+
# already waits for delivery.
98+
self._pump(flush_event)
7699

77-
def _ensure_worker_locked(
78-
self,
79-
) -> tuple[dict[str, Any] | None, Exception | None]:
100+
def _ensure_worker_locked(self) -> Exception | None:
80101
if self._worker is not None and self._worker.is_alive():
81-
return None, None
102+
return None
82103
worker = threading.Thread(
83104
target=self._run,
84105
name=f"workflow-insight-export-{id(self)}",
@@ -88,32 +109,45 @@ def _ensure_worker_locked(
88109
try:
89110
worker.start()
90111
except Exception as exc: # noqa: BLE001 - instrumentation must not escape hooks
91-
self._disabled = True
112+
# Leave the pending records in place: drain() exports them inline,
113+
# and a later schedule() retries starting a worker.
92114
self._worker = None
93-
failed_pending = self._pending
94-
self._pending = None
95-
failed_event = self._flush_event
96-
self._flush_event = None
97-
self._flush_requested = False
98-
if failed_event is not None:
99-
failed_event.set()
100-
return failed_pending, exc
101-
return None, None
115+
return exc
116+
return None
117+
118+
def _log_start_failure(self, start_error: Exception | None) -> None:
119+
if start_error is None or self._start_failure_logged:
120+
return
121+
self._start_failure_logged = True
122+
_logger.warning(
123+
"workflow-insight: could not start export worker; records are "
124+
"exported inline at invocation end instead: %s",
125+
start_error,
126+
)
127+
128+
def _pop_pending_locked(self) -> dict[str, Any] | None:
129+
if not self._pending:
130+
return None
131+
key = next(iter(self._pending))
132+
return self._pending.pop(key)
133+
134+
def _take_flush_locked(self) -> threading.Event | None:
135+
flush_event = self._flush_event
136+
self._flush_event = None
137+
self._flush_requested = False
138+
return flush_event
102139

103140
def _run(self) -> None:
104141
while True:
105142
record: dict[str, Any] | None = None
106143
flush_event: threading.Event | None = None
107144
with self._condition:
108-
while self._pending is None and not self._flush_requested:
145+
while not self._pending and not self._flush_requested:
109146
self._condition.wait()
110-
if self._pending is not None:
111-
record = self._pending
112-
self._pending = None
113-
else:
114-
flush_event = self._flush_event
115-
self._flush_event = None
116-
self._flush_requested = False
147+
record = self._pop_pending_locked()
148+
if record is None:
149+
# Every pending record is exported: honor the flush request.
150+
flush_event = self._take_flush_locked()
117151

118152
if record is not None:
119153
self._export(record)
@@ -123,10 +157,25 @@ def _run(self) -> None:
123157
if flush_event is not None:
124158
flush_event.set()
125159
with self._condition:
126-
if self._pending is None and not self._flush_requested:
160+
if not self._pending and not self._flush_requested:
127161
self._worker = None
128162
return
129163

164+
def _pump(self, flush_event: threading.Event) -> None:
165+
"""Export every pending record, then flush, on the calling thread."""
166+
while True:
167+
with self._condition:
168+
record = self._pop_pending_locked()
169+
if record is None:
170+
# Another inline drain may already have taken the request;
171+
# flushing twice is harmless, losing a record is not.
172+
self._take_flush_locked()
173+
if record is None:
174+
break
175+
self._export(record)
176+
self._flush()
177+
flush_event.set()
178+
130179
def _export(self, record: dict[str, Any]) -> None:
131180
for exporter in self._exporters:
132181
try:
@@ -159,4 +208,4 @@ def _worker_alive(self) -> bool:
159208

160209
def _pending_count(self) -> int:
161210
with self._condition:
162-
return int(self._pending is not None)
211+
return len(self._pending)

packages/aws-durable-execution-sdk-python-insight/src/aws_durable_execution_sdk_python_insight/plugin.py

Lines changed: 31 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -160,7 +160,7 @@ def _apply_result_override(
160160

161161

162162
class _ExecutionState:
163-
__slots__ = ("start_time", "parsed_arn", "cached_input", "operations")
163+
__slots__ = ("start_time", "parsed_arn", "cached_input", "operations", "closed")
164164

165165
def __init__(self, start_time: Any, parsed_arn: dict[str, str]) -> None:
166166
self.start_time = start_time
@@ -169,6 +169,10 @@ def __init__(self, start_time: Any, parsed_arn: dict[str, str]) -> None:
169169
# operation_id -> OperationInfo, adopted verbatim from the SDK's
170170
# authoritative snapshot (invocation start/end and operation-change).
171171
self.operations: dict[str, OperationInfo] = {}
172+
# Set by on_invocation_end before it emits. An operation-change hook
173+
# from a checkpoint that completes during the end-of-invocation drain
174+
# is dropped, so no RUNNING snapshot can follow the final record.
175+
self.closed = False
172176

173177

174178
class WorkflowInsightPlugin(DurableInstrumentationPlugin):
@@ -230,6 +234,23 @@ def _discard_state(self, execution_arn: str) -> None:
230234
with self._lock:
231235
self._state.pop(execution_arn, None)
232236

237+
def _open_state(self, execution_arn: str) -> _ExecutionState | None:
238+
"""Return the execution's state only while its invocation is open.
239+
240+
Unlike ``_ensure_state`` this never creates state: an operation-change
241+
hook always follows an invocation start, so missing state means the
242+
invocation already ended and its state was discarded.
243+
"""
244+
with self._lock:
245+
state = self._state.get(execution_arn)
246+
if state is None or state.closed:
247+
return None
248+
return state
249+
250+
def _close_state(self, state: _ExecutionState) -> None:
251+
with self._lock:
252+
state.closed = True
253+
233254
def _adopt_operations(
234255
self, state: _ExecutionState, operations: dict[str, OperationInfo]
235256
) -> None:
@@ -270,7 +291,11 @@ def on_operation_change(self, info: OperationChangeInfo) -> None:
270291
arn = info.execution_arn
271292
if not arn or not self._sampled_in(arn):
272293
return
273-
state = self._ensure_state(arn)
294+
state = self._open_state(arn)
295+
if state is None:
296+
# The invocation already ended (or is draining its final record);
297+
# a snapshot from a checkpoint that completed late is stale.
298+
return
274299
# Replace state with the full operations snapshot carried by the hook.
275300
self._adopt_operations(state, info.operations)
276301
# on-change mode exports an updated RUNNING record on each change so
@@ -297,6 +322,10 @@ def on_invocation_end(self, info: InvocationEndInfo) -> None:
297322
# Refresh from the fresh end-of-invocation snapshot before emitting so
298323
# the terminal record reflects the final operation map.
299324
self._adopt_operations(state, info.operations)
325+
# Close before emitting: an operation-change hook arriving from a
326+
# checkpoint that completes during the drain below is rejected, so no
327+
# RUNNING snapshot can follow (or replace) the final record.
328+
self._close_state(state)
300329
status = _STATUS_MAP.get(info.status, "RUNNING")
301330
is_terminal = status in ("SUCCEEDED", "FAILED")
302331
is_failure = status == "FAILED"

0 commit comments

Comments
 (0)