Fix avg_llm_latency ATIF evaluator always reporting 0.0

[AnishPatel526]

Fix avg_llm_latency ATIF evaluator always reporting 0.0

Reference Issues/PRs

Closes #2116.

What does this implement/fix? Explain your changes.

AverageLLMLatencyAtifEvaluator computed per-step LLM latency from
step.extra["span_event_timestamp"] (an ISO start paired with step.timestamp
as the end). That key never exists on a converted ATIF step: Step.extra is
built through AtifStepExtra, which is ConfigDict(extra="forbid") and defines
only ancestry / invocation / tool fields. span_event_timestamp is a field
on the pre-conversion IntermediateStep.payload, not on the post-conversion
Step.extra. So the evaluator was reading a pre-conversion field name off a
post-conversion object and always found nothing, leaving latencies empty and
the score 0.0.

The converter folds that pre-conversion field into the invocation timing:
nat/utils/atif_converter.py::_atif_invocation_from_ist sets
invocation.start_timestamp = ist.payload.span_event_timestamp (epoch seconds),
and the emitted step carries metrics=pending.metrics, so it clears the
evaluator's if step.source != "agent" or not step.metrics: continue guard.
That is the path this PR fixes.

Fix

Read the timing the converter actually writes. A new helper _step_llm_latency
prefers step.extra["invocation"] (end_timestamp - start_timestamp), rejects
non-finite / overflowing values, and falls back to the legacy
span_event_timestamp + step.timestamp pair so any producer emitting that
shape (and the existing tests for it) keeps working. Steps with neither source
are skipped rather than scored as a spurious zero.

Before / after

For a real converted ATIF agent step:

step.extra = {"invocation": {"start_timestamp": 1000.0, "end_timestamp": 1003.5}}

• Before: span_event_timestamp absent (and forbidden by the schema) ->
  latencies == [] -> score == 0.0.
• After: invocation used -> score == 3.5.

The legacy span_event_timestamp path is unchanged (still 5.0 for the
existing 5-second fixture).

Known follow-up (out of scope here)

The ATOF-script converter atof_to_atif_converter.py emits invocation timing
but sets no metrics, so its steps are dropped by the evaluator's not step.metrics guard and would still score 0.0 after this change, for a
separate reason. Worth a follow-up issue; this PR does not attempt to change
that producer.

Testing

Added tests in
packages/nvidia_nat_profiler/tests/profiler/test_runtime_evaluator_atif.py:

• test_evaluate_atif_item_uses_invocation_timing uses the converter's real
  extra["invocation"] shape (with a conflicting span_event_timestamp present
  to prove invocation takes precedence) and asserts a non-zero average. It
  fails on develop (score 0.0) and passes with this change.
• test_evaluate_atif_item_skips_non_finite_invocation_timing covers NaN, inf,
  and an integer too large to convert to float.

The existing span_event_timestamp tests continue to pass via the fallback.
ruff check and ruff format are clean on both changed files.

Checklist

• "closes avg_llm_latency evaluator always reports 0.0 — ATIF evaluator reads a key the ATIF converter never writes #2116" is in the PR body.
• New/changed code is tested (regression test that fails before the fix).
• Documentation updated where applicable (N/A, behavior fix, no API change).
• Commits are signed off (DCO).

[copy-pr-bot]

This pull request requires additional validation before any workflows can run on NVIDIA's runners.

Pull request vetters can view their responsibilities here.

Contributors can view more details about this message here.

[coderabbitai]

Walkthrough

The ATIF average LLM latency evaluator now prioritizes invocation epoch timestamps, falls back to legacy timestamps, skips invalid timing data, and includes regression tests for invocation timing and non-finite values.

Changes

ATIF latency evaluation

Layer / File(s)	Summary
Latency extraction helper packages/nvidia_nat_profiler/src/nat/plugins/profiler/runtime_evaluator/atif_evaluate.py	Adds a typed helper that computes non-negative latency from invocation timestamps and falls back to legacy ISO timestamp fields.
Evaluator integration and regression coverage packages/nvidia_nat_profiler/src/nat/plugins/profiler/runtime_evaluator/atif_evaluate.py, packages/nvidia_nat_profiler/tests/profiler/test_runtime_evaluator_atif.py	Updates the evaluator to record only valid helper results and tests invocation-based latency, call counts, recorded values, and non-finite timing exclusion.

Estimated code review effort: 2 (Simple) | ~10 minutes

🚥 Pre-merge checks | ✅ 5

✅ Passed checks (5 passed)

Check name	Status	Explanation
Linked Issues check	✅ Passed	The changes address #2116 by using converter-emitted invocation timing and adding regression coverage.
Out of Scope Changes check	✅ Passed	The code and tests stay focused on avg_llm_latency timing handling with no clear unrelated changes.
Docstring Coverage	✅ Passed	Docstring coverage is 80.00% which is sufficient. The required threshold is 80.00%.
Description Check	✅ Passed	Check skipped - CodeRabbit’s high-level summary is enabled.
Title check	✅ Passed	The title is concise, descriptive, uses imperative mood, and accurately identifies the evaluator defect being fixed.

✨ Finishing Touches

🧪 Generate unit tests (beta)

• Create PR with unit tests

---

_{Comment @coderabbitai help to get the list of available commands.}

[coderabbitai]

Actionable comments posted: 4

🤖 Prompt for all review comments with AI agents

Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.

Inline comments:
In
`@packages/nvidia_nat_profiler/src/nat/plugins/profiler/runtime_evaluator/atif_evaluate.py`:
- Around line 37-48: Update the docstring of _step_llm_latency to remove the
rejected “NAT” term, replacing it with “the ATOF-to-ATIF converter” or the
approved full product name while preserving the existing meaning.
- Around line 80-82: Update the evaluator class docstring near the latency
aggregation logic to document the new timing precedence: use extra["invocation"]
when available, fall back to span_event_timestamp, and skip steps only when
neither timing source exists.
- Around line 52-55: Update the timestamp validation in the invocation duration
evaluation to reject non-finite values and integers that cannot be safely
converted to float before calling float(start) or float(end). Skip such
invocations rather than computing a score, while preserving the existing
non-negative duration behavior for valid finite timestamps.

In `@packages/nvidia_nat_profiler/tests/profiler/test_runtime_evaluator_atif.py`:
- Around line 122-126: Update the docstring of
test_evaluate_atif_item_uses_invocation_timing so its opening sentence is
concise and ends with a period, and format the avg_llm_latency identifier with
backticks. Preserve the test’s existing meaning and regression context.

🪄 Autofix (Beta)

Fix all unresolved CodeRabbit comments on this PR:

• Push a commit to this branch (recommended)
• Create a new PR with the fixes

---

ℹ️ Review info

⚙️ Run configuration

Configuration used: Path: .coderabbit.yaml

Review profile: CHILL

Plan: Enterprise

Run ID: fa37b017-cb84-4eb4-bf28-ed48528318d4

📥 Commits

Reviewing files that changed from the base of the PR and between baf355b and ccfdecb.

📒 Files selected for processing (2)

• packages/nvidia_nat_profiler/src/nat/plugins/profiler/runtime_evaluator/atif_evaluate.py
• packages/nvidia_nat_profiler/tests/profiler/test_runtime_evaluator_atif.py

[coderabbitai]

Actionable comments posted: 1

🧹 Nitpick comments (1)

packages/nvidia_nat_profiler/tests/profiler/test_runtime_evaluator_atif.py (1)

122-146: 🎯 Functional Correctness | 🔵 Trivial | ⚡ Quick win

Test invocation-timing precedence explicitly.

This verifies that invocation timestamps work, but not that they take precedence over legacy timing. Add a conflicting extra["span_event_timestamp"] value and keep the expected latency at 3.5; otherwise a fallback-first implementation could still pass this regression test.

🤖 Prompt for AI Agents

Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.

In `@packages/nvidia_nat_profiler/tests/profiler/test_runtime_evaluator_atif.py`
around lines 122 - 146, Update test_evaluate_atif_item_uses_invocation_timing to
include a conflicting extra["span_event_timestamp"] value alongside
extra["invocation"], while keeping the expected latency and reasoning assertions
at 3.5 and one call. This must verify that invocation timing takes precedence
over legacy span-event timing.

🤖 Prompt for all review comments with AI agents

Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.

Inline comments:
In `@packages/nvidia_nat_profiler/tests/profiler/test_runtime_evaluator_atif.py`:
- Around line 149-154: Update the docstring of
test_evaluate_atif_item_skips_non_finite_invocation_timing to match the cases
actually exercised: either add a large-integer overflow scenario to the test or
remove the “and overflowing” claim, while preserving the existing NaN and inf
coverage.

---

Nitpick comments:
In `@packages/nvidia_nat_profiler/tests/profiler/test_runtime_evaluator_atif.py`:
- Around line 122-146: Update test_evaluate_atif_item_uses_invocation_timing to
include a conflicting extra["span_event_timestamp"] value alongside
extra["invocation"], while keeping the expected latency and reasoning assertions
at 3.5 and one call. This must verify that invocation timing takes precedence
over legacy span-event timing.

🪄 Autofix (Beta)

Fix all unresolved CodeRabbit comments on this PR:

• Push a commit to this branch (recommended)
• Create a new PR with the fixes

---

ℹ️ Review info

⚙️ Run configuration

Configuration used: Path: .coderabbit.yaml

Review profile: CHILL

Plan: Enterprise

Run ID: 9a1fe0de-be7e-4470-b5fa-7feb22d0e167

📥 Commits

Reviewing files that changed from the base of the PR and between ccfdecb and 7939f4b.

📒 Files selected for processing (2)

• packages/nvidia_nat_profiler/src/nat/plugins/profiler/runtime_evaluator/atif_evaluate.py
• packages/nvidia_nat_profiler/tests/profiler/test_runtime_evaluator_atif.py

🚧 Files skipped from review as they are similar to previous changes (1)

• packages/nvidia_nat_profiler/src/nat/plugins/profiler/runtime_evaluator/atif_evaluate.py

[AnishPatel526]

This is a non-breaking bug fix (avg_llm_latency always returned 0.0 because the evaluator read span_event_timestamp, which the ATOF-to-ATIF converter never writes). Could a maintainer apply the bug and non-breaking labels so the Label Checker can pass? Happy to adjust if you'd categorize it differently.

[AnishPatel526]

Hi! Just wanted to follow up on this contribution!

[chuenchen309]

I checked this independently against develop (2618705). The diagnosis holds, and there's a stronger form of the argument plus one open question about which producer actually benefits.

The key the evaluator reads cannot legally exist. AverageLLMLatencyAtifEvaluator reads step.extra.get("span_event_timestamp") (atif_evaluate.py:53). Step extras are built through AtifStepExtra, which declares model_config = ConfigDict(extra="forbid") and defines only ancestry, invocation, tool_ancestry, tool_invocations. So span_event_timestamp isn't merely absent from the current producers — the typed contract for Step.extra forbids it. Across the repo, extra={"span_event_timestamp": ...} appears only in test fixtures (test_runtime_evaluator_atif.py, and one dict in examples/dynamo_integration/.../test_tsq_formula.py); no production path writes it.

Both converters emit the invocation shape, so the fix is broader than the PR description claims:

• atof_to_atif_converter.py writes extra = {"ancestry": …, "invocation": _build_invocation_info(…)}, with start_timestamp / end_timestamp as epoch seconds (round(micros / 1_000_000, 3)).
• nat/utils/atif_converter.py writes extra=AtifStepExtra(…, invocation=pending.invocation, …).model_dump(exclude_none=True), where _atif_invocation_from_ist sets start_timestamp=ist.payload.span_event_timestamp.

That second one is the crisp statement of the bug: span_event_timestamp is a field on the pre-conversion IntermediateStep.payload, and the converter's job is to fold it into invocation.start_timestamp. The evaluator was reading the pre-conversion field name off a post-conversion object, so it always missed.

The open question — which producer does this actually unblock? The loop skips steps before it ever looks at timing:

if step.source != "agent" or not step.metrics:
    continue

nat/utils/atif_converter.py sets metrics=pending.metrics on the very step whose extra carries invocation, so those steps clear the guard and this fix does change their score. But atof_to_atif_converter.py — the producer the PR description cites — contains no metrics key at all: grep -n metrics over that file is empty, so every step it emits is dropped by not step.metrics regardless of this change. Unless something downstream in the ATOF pipeline attaches metrics (I didn't find it, but I may have missed a stage), ATOF-converted trajectories would still score 0.0 after this PR, for a second and separate reason.

None of that argues against merging — the timing lookup is wrong either way and the fallback keeps the legacy shape working. It does suggest the description would be more accurate pointing at nat/utils/atif_converter.py as the path this actually fixes, and that ATOF-script output may need a follow-up.

One small note on the fallback: it's keyed on isinstance(start, (int, float)), which is right for both converters since AtifInvocationInfo.start_timestamp is float | None in epoch seconds, while the legacy fixtures use ISO strings and fall through to _iso_to_epoch. The two shapes differ in both key and type, so they can't collide.

AI-assisted review. The contract, converter and evaluator code above were read on develop at 2618705; I did not run the test suite locally, so the pass/fail claims in the PR description are not independently confirmed here.

[AnishPatel526]

Updated the description to point at nat/utils/atif_converter.py as the path this fixes, and added a note that the ATOF-script producer (atof_to_atif_converter.py) emits no metrics so its steps stay at 0.0, worth a separate follow-up. Thanks again for the diagnosis!