DeferrableMetrics: emit INFO event on Future-backed deferred failure (#4275)#4312
Open
kaanbaloglu wants to merge 1 commit into
Open
DeferrableMetrics: emit INFO event on Future-backed deferred failure (#4275)#4312kaanbaloglu wants to merge 1 commit into
kaanbaloglu wants to merge 1 commit into
Conversation
…eta-pytorch#4275) Summary: Closes an observability gap on the Future-backed path of `DeferrableMetrics`. `RecMetricModule.compute` is decorated with `EventLoggingHandler.event_logger(REC_METRICS)`, which emits SUCCESS as soon as `compute()` returns. When `compute()` returns a `DeferrableMetrics` wrapping a Future, the actual metric computation runs on a worker thread and may raise long after the decorator already logged SUCCESS. The consumer's `resolve()` or `subscribe()` then raises outside the decorator's scope, so the failure never reaches `torchrec_event_logging`. From a 7d analysis of silent APS DEAD attempts (joined torchrec_event_logging ∩ mast_hpc_job_run_status), ~33% last logged `RecMetricModule.compute` as SUCCESS before dying — roughly 1,100 APS attempts/week with no torchrec-side attribution. `DeferrableMetrics.__init__` now registers an internal `add_done_callback` on Future-backed instances. The callback runs `f.result()` in a try/except; on exception it synchronously calls `EventLoggingHandler.log_event` with `event_type=INFO`, `event_name='DeferrableMetrics.deferred_failure'`, and metadata carrying `exception_type`, truncated `error_message`, and truncated `stack_trace`. Telemetry exceptions are swallowed so the caller is never affected. The done-callback fires once per Future regardless of whether `resolve()` / `subscribe()` is ever called, so unobserved futures still surface their failures. Pre-resolved (non-Future) instances are not instrumented. Mirrors the per-site capture pattern from `DataLoadingThread` (D105462584): instrument at the boundary where the Future actually resolves, not where the wrapping call returned. **Design choices**: - **Synchronous emit, no background worker / queue / daemon thread**. Matches the existing pattern in `torchrec/metrics/cpu_offloaded_metric_module.py:557` (the metric worker thread itself runs synchronous `EventLoggingHandler.event_logger` calls) and `metric_module.py:339,412`. The FB shim adds to an in-memory Scuba sample buffer; per-call cost is microseconds. - **`event_type=INFO`, not `FAILURE`**. Per Nipun's review on D105462584, the dataset invariant `#START == #SUCCESS + #FAILURE` requires every FAILURE to pair with a START. Standalone failure records should use INFO. The START/SUCCESS for the enclosing `RecMetricModule.compute` call is already emitted by the existing decorator; we don't need to duplicate it. - **No JK gate**. Pure additive observability — no behavior change for any caller. `resolve()` / `subscribe()` / `update()` return the same values and raise the same exceptions. The only new artifact is rows in `torchrec_event_logging`. Existing RecMetrics decorators are also unconditional; this matches the local convention. - **Defensive import block for `EventLoggingHandler` / `TorchrecComponent` / `EventType`**. Mirrors the guarded import in `metric_module.py:30-65` and `cpu_offloaded_metric_module.py:27-65`. `DeferrableMetrics` is imported by `metric_module.py`, which gets packaged into inference paths without the logging handler shim; an unconditional import here would break those packages. The fallback substitutes a no-op `log_event`. **Known tradeoff**: emit is unsampled. Per-process volume is bounded by `Future-backed metric computations × ranks`. Typical APS eval job (~10 compute calls × ~128 ranks) caps at ~1,280 events for a persistent-failure run — small relative to the 200K+ events / 28d already on `torchrec_event_logging`. If canary shows a single job emitting tens of thousands, the right follow-up is a process-local cap (first N per `exception_type` then drop with one warning). Sampling tools (`n_batch_log_event`) lose signal in non-APF contexts where the batch counter isn't updated. Scope: only `DeferrableMetrics` Future-backed instances. `RecMetricModule.update` / `compute` decorators unchanged; per-metric implementations unchanged. Anything that wraps a Future in a different container (raw `Future`, custom awaitable) is not covered. Differential Revision: D107334098
Contributor
|
@kaanbaloglu has exported this pull request. If you are a Meta employee, you can view the originating Diff in D107334098. |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary:
Closes an observability gap on the Future-backed path of
DeferrableMetrics.RecMetricModule.computeis decorated withEventLoggingHandler.event_logger(REC_METRICS), which emits SUCCESS as soon ascompute()returns. Whencompute()returns aDeferrableMetricswrapping a Future, the actual metric computation runs on a worker thread and may raise long after the decorator already logged SUCCESS. The consumer'sresolve()orsubscribe()then raises outside the decorator's scope, so the failure never reachestorchrec_event_logging. From a 7d analysis of silent APS DEAD attempts (joined torchrec_event_logging ∩ mast_hpc_job_run_status), ~33% last loggedRecMetricModule.computeas SUCCESS before dying — roughly 1,100 APS attempts/week with no torchrec-side attribution.DeferrableMetrics.__init__now registers an internaladd_done_callbackon Future-backed instances. The callback runsf.result()in a try/except; on exception it synchronously callsEventLoggingHandler.log_eventwithevent_type=INFO,event_name='DeferrableMetrics.deferred_failure', and metadata carryingexception_type, truncatederror_message, and truncatedstack_trace. Telemetry exceptions are swallowed so the caller is never affected. The done-callback fires once per Future regardless of whetherresolve()/subscribe()is ever called, so unobserved futures still surface their failures. Pre-resolved (non-Future) instances are not instrumented.Mirrors the per-site capture pattern from
DataLoadingThread(D105462584): instrument at the boundary where the Future actually resolves, not where the wrapping call returned.Design choices:
torchrec/metrics/cpu_offloaded_metric_module.py:557(the metric worker thread itself runs synchronousEventLoggingHandler.event_loggercalls) andmetric_module.py:339,412. The FB shim adds to an in-memory Scuba sample buffer; per-call cost is microseconds.event_type=INFO, notFAILURE. Per Nipun's review on D105462584, the dataset invariant#START == #SUCCESS + #FAILURErequires every FAILURE to pair with a START. Standalone failure records should use INFO. The START/SUCCESS for the enclosingRecMetricModule.computecall is already emitted by the existing decorator; we don't need to duplicate it.resolve()/subscribe()/update()return the same values and raise the same exceptions. The only new artifact is rows intorchrec_event_logging. Existing RecMetrics decorators are also unconditional; this matches the local convention.EventLoggingHandler/TorchrecComponent/EventType. Mirrors the guarded import inmetric_module.py:30-65andcpu_offloaded_metric_module.py:27-65.DeferrableMetricsis imported bymetric_module.py, which gets packaged into inference paths without the logging handler shim; an unconditional import here would break those packages. The fallback substitutes a no-oplog_event.Known tradeoff: emit is unsampled. Per-process volume is bounded by
Future-backed metric computations × ranks. Typical APS eval job (~10 compute calls × ~128 ranks) caps at ~1,280 events for a persistent-failure run — small relative to the 200K+ events / 28d already ontorchrec_event_logging. If canary shows a single job emitting tens of thousands, the right follow-up is a process-local cap (first N perexception_typethen drop with one warning). Sampling tools (n_batch_log_event) lose signal in non-APF contexts where the batch counter isn't updated.Scope: only
DeferrableMetricsFuture-backed instances.RecMetricModule.update/computedecorators unchanged; per-metric implementations unchanged. Anything that wraps a Future in a different container (rawFuture, custom awaitable) is not covered.Differential Revision: D107334098