Skip to content

fix(telemetry): end call_llm span before the flow runs tools - #7628

Draft
ahlag wants to merge 1 commit into
google:mainfrom
ahlag:fix-7625-model-span-boundary
Draft

ahlag wants to merge 1 commit into
google:mainfrom
ahlag:fix-7625-model-span-boundary

Conversation

@ahlag

@ahlag ahlag commented Oct 20, 2026 •

Copy link
Copy Markdown

Please ensure you have read the contribution guide before creating a pull request.

Link to Issue or Description of Change

1. Link to an existing issue (if applicable):

Problem:

_run_one_step_async runs _postprocess_async, and so the tools, inside the async for over _call_llm_async. The model-call generator is suspended at its yield while the tools run. call_llm is opened in _model_call.py and was only ended in the generator's finally, which runs after the tools, so its duration included all of the downstream tool time.

generate_content (schema v2) already ends at the response when a finish reason is reported (6364060). This makes call_llm (schema v1) behave the same way.

Solution:

  • End call_llm before yielding the final non-partial response that reports a finish reason, after trace_call_llm and the after-model callback have run.
  • The finally now checks is_recording(), so aclose() / early termination, and responses without a finish reason, still end the span exactly once at teardown.
  • Partial chunks never end the span. Ending on the partial chunk that carries the finish reason broke the v1 streaming goldens and logged "Calling end() on an ended span".

Parentage is unchanged: execute_tool is already a child of invoke_agent, not of the model spans (83d966c).

Out of scope, left for discussion on #7625: responses that report no finish reason (as in the issue's fake model) still keep both model spans open until generator teardown. Closing them there would require pulling ahead on the generator.

Testing Plan

Unit Tests:

  • I have added or updated unit tests for my change.
  • All unit tests pass locally (except one pre-existing macOS failure, see below).

New test test_model_spans_end_before_the_tool_call_starts in tests/unittests/telemetry/test_functional.py, parametrized over streaming / non-streaming and schema v1 / v2. It asserts that every model span ends before the next execute_tool span starts. It checks span order, not timings, so it isn't timing-sensitive. Without the fix, the two v1 cases fail.

tox (pytest tests/unittests) on macOS arm64:

py311: 1 failed, 20494 passed, 95 skipped, 19 xfailed, 2 xpassed
py312: 1 failed, 20485 passed, 96 skipped, 19 xfailed, 2 xpassed
py313: 1 failed, 20485 passed, 96 skipped, 19 xfailed, 2 xpassed
py314: 1 failed, 20486 passed, 95 skipped, 19 xfailed, 2 xpassed

The one failure is tests/unittests/integrations/vmaas/test_agent_engine_environment.py::test_reading_directory_raises (DID NOT RAISE OSError). It fails the same way on unmodified main (8909689) on macOS and is unrelated to this change.

Manual End-to-End (E2E) Tests:

The standalone script from #7625 with a fake model that reports finish_reason=STOP: model delay 0.1 s, tool delay 1.0 s, ADK_TELEMETRY_SCHEMA_VERSION_OPT_IN=1.

Span Mode Before After Tool overlap after
call_llm non-streaming 1.11 s 0.103 s 0
call_llm streaming 1.21 s 0.204 s 0
generate_content non-streaming 0.102 s 0.102 s 0
generate_content streaming 0.204 s 0.204 s 0

Checklist

  • I have read the CONTRIBUTING.md document.
  • I have performed a self-review of my own code.
  • I have commented my code, particularly in hard-to-understand areas.
  • I have added tests that prove my fix is effective or that my feature works.
  • New and existing unit tests pass locally with my changes.
  • I have manually tested my changes end-to-end.
  • Any dependent changes have been merged and published in downstream modules.

Additional context

I know call_llm is deprecated (v1 is supported until 2027-03-31). If you'd rather not change v1, I'm happy to cut this down to the test plus a docs note on the no-finish-reason case.

The model call generator is suspended at its yield while the flow
post-processes the response (runs tools), and call_llm was only ended in
the generator's finally, so its duration included downstream tool time.

End call_llm before yielding the final non-partial response that reports
a finish reason, after trace_call_llm and the after-model callback. The
finally still ends it on early close or when no finish reason is reported.

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

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Model spans include downstream tool time after yielding the final response

2 participants