Skip to content

Add persistent performance telemetry and timing metrics to auto_agent - #94

Merged
stingram merged 9 commits into
mainfrom
si/timing_metrics
Aug 31, 2026
Merged

Add persistent performance telemetry and timing metrics to auto_agent#94
stingram merged 9 commits into
mainfrom
si/timing_metrics

Conversation

@stingram

@stingram stingram commented Aug 25, 2026

Copy link
Copy Markdown
Collaborator

Add Timing Metrics

Summary

This PR upgrades the timing mechanics across the Auto-Agent framework to include timing information for users. Previously, execution timing was obscured by overlapping hierarchical wait times (e.g., framework overhead bounds were mistakenly inflated by IO bottlenecks). This PR introduces precise chronological event tracking via float timestamps, automatically merges these timestamps into "Exclusive Compute" bounds (Flamegraph-style self-time), and links it all through an automated reporting script that prints to the console and generates markdown metrics.

Changes

  • Upgraded Telemetry Infrastructure (auto_agent/timing_callbacks.py)
    • Updated the state dictionary configuration and Pydantic models to track exact UNIX float sequences (start_time, end_time) instead of just total durational times.
    • Isolated dictionary persistence states directly to specific Agent namespaces (_llm_start_{agent}) to ensure bounds process safely during parallel asynchronous executions.
    • Extracted agent orchestration metrics into an independent agent_events data payload to prevent downstream summation crashes.
  • Trace Analyzer (auto_search/analyze_timing.py)
    • Created a dedicated node-crawler that scans recursive directory structures to globally map timing_metrics.json outputs.
    • Includes interval intersection union algorithms that effectively map Inclusive execution bounds out to true Exclusive Self-Time. Nested Sub-Agents, LLM calls, and Tool interactions are now subtracted from calling Agent durations so that metric aggregations are accurate.
  • Automated Job Completions (auto_search/run_search.py)
    • Hooked the analyze_timing parser natively to the final termination step of successful beam and parallel searches, ensuring that users automatically receive a terminal printout and a formatted timing_summary.md in the target tracking directory exactly when their task safely concludes.
  • Repository Architecture Cleanup (.gitignore, /examples)
    • Migrated the mock kernel proxy scripts into examples/dummy_kernel/ for proper localization.
    • Added the .gitignore rule-set against tracking the Python local package environment (.venv).

Example Outputs

Click to expand: Example timing_metrics.json (Truncated payload view)
{
  "overall_pipeline_time": 548.34,
  "iterations": {
    "0": {
      "iteration_total_time": 548.34,
      "llm_calls": [
        {
          "agent": "RunTestsAgent",
          "start_time": 1729000010.5,
          "end_time": 1729000085.2
        }
      ],
      "tools": [
        {
          "agent": "MockTestExecutionAgent",
          "start_time": 1729000092.1,
          "end_time": 1729000094.0
        }
      ],
      "agent_events": [
        {
          "agent": "AutotuneRunner",
          "start_time": 1729000000.0,
          "end_time": 1729000200.0
        }
      ]
    }
  }
}
Click to expand: Example timing_summary.md (Parser Output)
============================================================
  FILE: timing_metrics.json (Node: node_001_attempt_1)
  PATH: /tmp/dummy_kernel_run_parallel_20260826_233506/nodes/node_001_attempt_1/timing_metrics.json
============================================================
--- Iteration 0 ---
  Total Iteration Time (Wall) :  548.34s
  LLM Wait Time (Wall)        :  451.21s  (82.3%)  [Calls: 56]
  Tool Exec Time (Wall)       :    5.86s  ( 1.1%)  [Calls: 43]
  True Framework Overhead     :   91.27s  (16.6%)
      -> Exclusive Non-IO Compute Breakdown (Excludes Child Logic):
         [Note: Agents with < 0.01s exclusive time are hidden/grouped into Orchestrator Bridge]
         * AutotuneRunner                                :  30.01s
         * MockTestExecutionAgent                        :  20.02s
         * RunTestsAgent                                 :  20.01s
         * ProfileEvalAgent                              :  10.27s
         * KernelCompilationCheckerForValidation         :  10.01s
         * PrepareBaseKernelAgent                        :   0.68s
         * ImplementKernelAgent                          :   0.06s
         * <Unaccounted Orchestrator Bridge>             :   0.21s

============================================================
        MACRO SUMMARY (ACROSS ALL DISCOVERED NODES)         
============================================================
Total Nodes/Attempts Analyzed : 1
Aggregated Pipeline Time   :  548.35s computation-hours
Total LLM Wait Time        :  451.21s  (82.3%)  [Calls: 56]
Total Tool Exec Time       :    5.86s  ( 1.1%)  [Calls: 43]
Total Framework Overhead   :   91.27s  (16.6%)
  -> Breakdown of Framework Overhead by Exclusive Component Compute:
       [Note: Agents with < 0.01s exclusive time are hidden/grouped into Orchestrator Bridge]
       * AutotuneRunner                                :  30.01s
       * MockTestExecutionAgent                        :  20.02s
       * RunTestsAgent                                 :  20.01s
       * ProfileEvalAgent                              :  10.27s
       * KernelCompilationCheckerForValidation         :  10.01s
       * PrepareBaseKernelAgent                        :   0.68s
       * ImplementKernelAgent                          :   0.06s
       * <Unaccounted Orchestrator Bridge>             :   0.21s
Other / Orchestrator Setup :    0.00s  ( 0.0%)
============================================================

@gemini-code-assist gemini-code-assist Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Code Review

This pull request introduces timing metrics tracking across the pipeline agent execution steps, registering callbacks globally and via a plugin to measure agent, LLM, and tool durations. The review feedback highlights several improvement opportunities: refactoring highly duplicated timing calculation blocks in pipeline_agent.py into a helper function, ensuring callbacks return the original request/response objects instead of None to avoid framework crashes, moving the module docstring in callbacks.py to the top of the file to comply with PEP 8, and replacing inline __import__('time') calls with standard top-level imports.

Comment thread MaxKernel/auto_agent/subagents/pipeline_agent.py Outdated
Comment thread MaxKernel/auto_agent/timing_callbacks.py Outdated
Comment thread MaxKernel/auto_agent/timing_callbacks.py Outdated
Comment thread MaxKernel/auto_agent/timing_callbacks.py Outdated
Comment thread MaxKernel/auto_agent/callbacks.py
Comment thread MaxKernel/auto_agent/subagents/pipeline_agent.py Outdated
@stingram stingram changed the title Added logic for capturing timing metrics. Add persistent performance telemetry and timing metrics to auto_agent Aug 25, 2026
@stingram

Copy link
Copy Markdown
Collaborator Author

/gemini review

@gemini-code-assist gemini-code-assist Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Code Review

This pull request introduces a telemetry and timing framework to track execution durations for agents, LLM calls, and tools across pipeline iterations, including a timing analysis script and mock end-to-end tests. The review feedback highlights several critical improvements: preventing state key collisions in concurrent environments by using unique context IDs, guarding against KeyError during analysis of interrupted runs, broadening exception handling during hook injection, preventing negative framework overhead calculations, and replacing a hardcoded user directory path in the mock tests with a relative path.

Comment thread MaxKernel/auto_agent/timing_callbacks.py Outdated
Comment thread MaxKernel/auto_agent/timing_callbacks.py Outdated
Comment thread MaxKernel/auto_agent/timing_callbacks.py Outdated
Comment thread MaxKernel/auto_search/utils/analyze_timing.py Outdated
Comment thread MaxKernel/auto_agent/agent.py Outdated
Comment thread MaxKernel/auto_agent/subagents/pipeline_agent.py Outdated
Comment thread MaxKernel/examples/dummy_kernel/mock_e2e_real.py Outdated
@stingram
stingram marked this pull request as ready for review August 28, 2026 19:02
Comment thread MaxKernel/auto_agent/timing_callbacks.py
Comment thread MaxKernel/auto_search/utils/analyze_timing.py
Comment thread MaxKernel/auto_agent/callbacks.py Outdated
Comment thread MaxKernel/auto_agent/timing_callbacks.py Outdated
@stingram
stingram merged commit 2b7f997 into main Aug 31, 2026
7 checks passed
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.

2 participants