Skip to content

Track timing on streaming /chat requests - #1307

Draft
aantn wants to merge 4 commits into
masterfrom
claude/streaming-timing-events-0sy5u
Draft

aantn wants to merge 4 commits into
masterfrom
claude/streaming-timing-events-0sy5u

Conversation

@aantn

@aantn aantn commented Jan 2, 2026 •

Copy link
Copy Markdown
Collaborator

Implements detailed timing information for all streaming API responses to help diagnose performance bottlenecks between server and frontend.

Changes:

  • Add TimingTracker class to track timing events throughout request lifecycle
  • Record timing for LLM completion calls (start/end with iteration and model info)
  • Record timing for tool calls (start/end with tool name and ID)
  • Record conversation history compaction events
  • Include elapsed_time_ms and timing_events array in every SSE message
  • Updated /api/chat and /api/stream/investigate endpoints to use timing tracker

Each SSE message now includes:

  • elapsed_time_ms: Total milliseconds since request started
  • timing_events: Array of all significant events with timestamps, descriptions, and metadata

This enables frontend to:

  • Compare server-side timing with client-side timing
  • Identify network latency between server and client
  • Detect slow LLM completion calls
  • Track intermediate streaming output for UX improvements

Summary by CodeRabbit

  • New Features

    • Adds end-to-end timing metrics for AI interactions and includes timing info in streaming responses and events.
  • Improvements

    • Timing is optional and non‑disruptive when disabled; timing events are better associated with individual tool calls and preserve exception context.
  • Documentation

    • Adds a performance diagnostic guide with timing event definitions, diagnostic theories, analysis steps, and example analysis scripts.

✏️ Tip: You can customize this high-level summary in your review settings.

Implements detailed timing information for all streaming API responses to help
diagnose performance bottlenecks between server and frontend.

Changes:
- Add TimingTracker class to track timing events throughout request lifecycle
- Record timing for LLM completion calls (start/end with iteration and model info)
- Record timing for tool calls (start/end with tool name and ID)
- Record conversation history compaction events
- Include elapsed_time_ms and timing_events array in every SSE message
- Updated /api/chat and /api/stream/investigate endpoints to use timing tracker

Each SSE message now includes:
- elapsed_time_ms: Total milliseconds since request started
- timing_events: Array of all significant events with timestamps, descriptions, and metadata

This enables frontend to:
- Compare server-side timing with client-side timing
- Identify network latency between server and client
- Detect slow LLM completion calls
- Track intermediate streaming output for UX improvements
@linux-foundation-easycla

linux-foundation-easycla Bot commented Jan 2, 2026 •

Copy link
Copy Markdown

CLA Not Signed

@coderabbitai

coderabbitai Bot commented Jan 2, 2026 •

Copy link
Copy Markdown
Contributor

Walkthrough

Adds a TimingEvent/TimingTracker system and threads timing through streaming and non‑stream LLM and tool call flows. Timing events (config, context limiting, llm_call, tool_call, history_compaction, etc.) are recorded and emitted with SSE stream messages; instrumentation is conditional on a provided timing_tracker.

Changes

Cohort / File(s) Summary
Timing infrastructure
holmes/utils/stream.py
Adds TimingEvent and TimingTracker, extends StreamMessage with timing, updates create_sse_message to accept timing_info, and adds timing-aware formatter APIs (stream_investigate_formatter, stream_chat_formatter) that accept an optional timing_tracker.
LLM call integration
holmes/core/tool_calling_llm.py
Adds optional timing_tracker parameter to call_stream, emits timing events around context limiting, per-iteration LLM call start/end, history compaction, and per-tool call start/end; tracks per-future tool metadata for mapping tool end events; preserves behavior when timing_tracker is None; adds from e in one BadRequestError path.
Server API integration
server.py
Imports TimingTracker, creates and passes timing_tracker into streaming request paths (ai.call_stream, formatters) and records timing events around config/DAL/message/prompt steps for streaming chat; non-stream path initializes tracker conditionally.
Docs / Guide
PERFORMANCE_DIAGNOSTIC_GUIDE.md
New performance diagnostic guide documenting timing events, diagnostic theories, example analysis script, checklist, and remediation guidance for measured timing traces.

Sequence Diagram(s)

sequenceDiagram
    autonumber
    actor Client
    participant Server
    participant TimingTracker as Tracker
    participant ToolCallingLLM as LLM
    participant Formatter

    Client->>Server: HTTP request (chat / investigate)
    Server->>Tracker: create / start relevant events
    Server->>LLM: call_stream(..., timing_tracker)
    alt LLM iterations
        LLM->>Tracker: record_event llm_call_start
        LLM->>LLM: limit input context
        LLM->>Tracker: record_event context_limiting_start/context_limiting_end
        LLM->>Tracker: record_event history_compaction (if occurred)
        opt tool invocation(s)
            LLM->>Tracker: record_event tool_call_start (attach future id & metadata)
            LLM->>LLM: schedule tool future
            Note right of LLM: futures complete asynchronously
            LLM->>Tracker: record_event tool_call_end (map by future id)
        end
        LLM->>Tracker: record_event llm_call_end
        LLM->>Formatter: yield StreamMessage (includes timing via tracker)
    end
    Formatter->>Server: SSE payloads with timing_info
    Server->>Client: SSE stream messages
Loading

Estimated code review effort

🎯 3 (Moderate) | ⏱️ ~25 minutes

Possibly related PRs

Suggested reviewers

  • moshemorad
  • Sheeproid

Pre-merge checks

❌ Failed checks (1 warning)
Check name Status Explanation Resolution
Docstring Coverage ⚠️ Warning Docstring coverage is 73.91% which is insufficient. The required threshold is 80.00%. You can run @coderabbitai generate docstrings to improve docstring coverage.
✅ Passed checks (2 passed)
Check name Status Explanation
Description Check ✅ Passed Check skipped - CodeRabbit’s high-level summary is enabled.
Title check ✅ Passed The title 'Track timing on streaming /chat requests' accurately summarizes the main change: adding timing instrumentation to streaming chat endpoints.

Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out.

❤️ Share

Comment @coderabbitai help to get the list of available commands and usage tips.

@github-actions

github-actions Bot commented Jan 2, 2026 •

Copy link
Copy Markdown
Contributor

✅ Docker image ready for 08478ff (built in 59s)

⚠️ Warning: does not support ARM (ARM images are built on release only - not on every PR)

Use this tag to pull the image for testing.

📋 Copy commands

⚠️ Temporary images are deleted after 30 days. Copy to a permanent registry before using them:

gcloud auth configure-docker us-central1-docker.pkg.dev
docker pull us-central1-docker.pkg.dev/robusta-development/temporary-builds/holmes:08478ff
docker tag us-central1-docker.pkg.dev/robusta-development/temporary-builds/holmes:08478ff me-west1-docker.pkg.dev/robusta-development/development/holmes-dev:08478ff
docker push me-west1-docker.pkg.dev/robusta-development/development/holmes-dev:08478ff

Patch Helm values in one line (choose the chart you use):

HolmesGPT chart:

helm upgrade --install holmesgpt ./helm/holmes \
  --set registry=me-west1-docker.pkg.dev/robusta-development/development \
  --set image=holmes-dev:08478ff

Robusta wrapper chart:

helm upgrade --install robusta robusta/robusta \
  --reuse-values \
  --set holmes.registry=me-west1-docker.pkg.dev/robusta-development/development \
  --set holmes.image=holmes-dev:08478ff

@coderabbitai coderabbitai 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.

Actionable comments posted: 1

🧹 Nitpick comments (1)
holmes/utils/stream.py (1)

60-76: Minor improvement: Avoid unnecessary string conversion of iteration.

Lines 66 and 75 convert iteration to a string when adding it to the metadata dictionary. Since Python dictionaries can store integers directly, this conversion is unnecessary and makes the data less strongly typed.

🔎 Proposed fix
 def record_llm_call_start(self, model: Optional[str] = None, iteration: Optional[int] = None):
     """Record the start of an LLM completion call."""
     metadata: dict = {}
     if model:
         metadata["model"] = model
     if iteration is not None:
-        metadata["iteration"] = str(iteration)
+        metadata["iteration"] = iteration
     self._add_event("llm_call_start", f"LLM completion call started (iteration {iteration})", metadata)

 def record_llm_call_end(self, model: Optional[str] = None, iteration: Optional[int] = None):
     """Record the end of an LLM completion call."""
     metadata: dict = {}
     if model:
         metadata["model"] = model
     if iteration is not None:
-        metadata["iteration"] = str(iteration)
+        metadata["iteration"] = iteration
     self._add_event("llm_call_end", f"LLM completion call completed (iteration {iteration})", metadata)
📜 Review details

Configuration used: Organization UI

Review profile: CHILL

Plan: Pro

📥 Commits

Reviewing files that changed from the base of the PR and between e3799f3 and 3221475.

📒 Files selected for processing (3)
  • holmes/core/tool_calling_llm.py
  • holmes/utils/stream.py
  • server.py
🧰 Additional context used
📓 Path-based instructions (1)
**/*.py

📄 CodeRabbit inference engine (CLAUDE.md)

**/*.py: Use Ruff for formatting and linting (configured in pyproject.toml)
Type hints required (mypy configuration in pyproject.toml)
ALWAYS place Python imports at the top of the file, not inside functions or methods

Files:

  • holmes/core/tool_calling_llm.py
  • holmes/utils/stream.py
  • server.py
🧬 Code graph analysis (2)
holmes/core/tool_calling_llm.py (1)
holmes/utils/stream.py (5)
  • record_history_compaction (86-88)
  • record_llm_call_start (60-67)
  • record_llm_call_end (69-76)
  • record_tool_call_start (78-80)
  • record_tool_call_end (82-84)
holmes/utils/stream.py (1)
holmes/core/tool_calling_llm.py (1)
  • call_stream (721-985)
⏰ Context from checks skipped due to timeout of 90000ms. You can increase the timeout in your CodeRabbit configuration to a maximum of 15 minutes (900000ms). (5)
  • GitHub Check: build
  • GitHub Check: build (3.10)
  • GitHub Check: build (3.11)
  • GitHub Check: build (3.12)
  • GitHub Check: llm_evals
🔇 Additional comments (3)
server.py (2)

190-204: LGTM! Clean timing integration in streaming endpoints.

The timing tracker is correctly instantiated per request and properly threaded through both the LLM call stream and the formatter. This pattern is consistently applied across streaming endpoints.


394-409: LGTM! Consistent timing tracker implementation.

The timing tracker integration in the chat streaming path follows the same clean pattern as the investigate endpoint, maintaining consistency across the codebase.

holmes/core/tool_calling_llm.py (1)

778-911: LGTM! Timing instrumentation is well-integrated.

The timing tracking logic is correctly placed at all key points:

  • History compaction events are recorded when the conversation is compacted
  • LLM call start/end events wrap the completion call
  • Tool call start events are recorded before submitting futures
  • Tool call end events are recorded after futures complete, using the futures_tool_info dictionary to correctly correlate async tool executions with their metadata

The defensive checks (if timing_tracker:) prevent errors when timing is not enabled, and all timing calls are made from the main thread, avoiding potential race conditions.

msgs: Optional[list[dict]] = None,
enable_tool_approval: bool = False,
tool_decisions: List[ToolApprovalDecision] | None = None,
timing_tracker = None, # TimingTracker instance for tracking timing events

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.

⚠️ Potential issue | 🟡 Minor

Add type hint for timing_tracker parameter.

Per the coding guidelines, type hints are required. The timing_tracker parameter should have a type hint indicating it accepts Optional[TimingTracker].

🔎 Proposed fix

First, add the import at the top of the file with the other imports from holmes.utils.stream (around line 60):

 from holmes.utils.stream import (
     StreamEvents,
     StreamMessage,
     add_token_count_to_metadata,
     build_stream_event_token_count,
+    TimingTracker,
 )

Then update the parameter with the type hint:

     def call_stream(
         self,
         system_prompt: str = "",
         user_prompt: Optional[str] = None,
         response_format: Optional[Union[dict, Type[BaseModel]]] = None,
         sections: Optional[InputSectionsDataType] = None,
         msgs: Optional[list[dict]] = None,
         enable_tool_approval: bool = False,
         tool_decisions: List[ToolApprovalDecision] | None = None,
-        timing_tracker = None,  # TimingTracker instance for tracking timing events
+        timing_tracker: Optional[TimingTracker] = None,
     ):
🤖 Prompt for AI Agents
In holmes/core/tool_calling_llm.py around line 730, the timing_tracker parameter
lacks a type hint; add imports for Optional (from typing) and TimingTracker
(from holmes.utils.stream) near the other imports (around line ~60), then change
the function signature to declare timing_tracker: Optional[TimingTracker] = None
so the parameter is properly typed as optional.

@github-actions

github-actions Bot commented Jan 2, 2026

Copy link
Copy Markdown
Contributor

✅ Results of HolmesGPT evals

Automatically triggered by commit 3221475 on branch claude/streaming-timing-events-0sy5u

View workflow logs

Results of HolmesGPT evals

  • ask_holmes: 9/9 test cases were successful, 0 regressions
Status Test case Time Turns Tools Cost
✅ 09_crashpod 31.6s ±0% 6 13 $0.1640
✅ 101_loki_historical_logs_pod_deleted 41.8s ↓25% 6 12 $0.1832
✅ 111_pod_names_contain_service 38.0s ↓11% 7 15 $0.1750
✅ 12_job_crashing 35.6s ↓25% 7 15 $0.1764
✅ 162_get_runbooks 52.5s ±0% 8 21 $0.2449
✅ 176_network_policy_blocking_traffic_no_runbooks 37.6s ±0% 6 15 $0.1738
✅ 24_misconfigured_pvc 35.4s ±0% 7 17 $0.1755
✅ 43_current_datetime_from_prompt 3.5s ±0% 1 — $0.0621
✅ 61_exact_match_counting 10.3s ±0% 3 3 $0.0860
Total 31.8s avg 5.7 avg 13.9 avg $1.4409

Time/Cost columns show % change vs historical average (↑slower/costlier, ↓faster/cheaper). Changes under 10% shown as ±0%.

Historical Comparison Details

Filter: excluding branch 'claude/streaming-timing-events-0sy5u'

Status: Success - 19 test/model combinations loaded

Experiments compared (30):

Comparison indicators:

  • ±0% — diff under 10% (within noise threshold)
  • ↑N%/↓N% — diff 10-25%
  • ↑N%/↓N% — diff over 25% (significant)
📖 Legend
Icon Meaning
✅ The test was successful
➖ The test was skipped
⚠️ The test failed but is known to be flaky or known to fail
🚧 The test had a setup failure (not a code regression)
🔧 The test failed due to mock data issues (not a code regression)
🚫 The test was throttled by API rate limits/overload
❌ The test failed and should be fixed before merging the PR
🔄 Re-run evals manually

⚠️ Warning: /eval comments always run using the workflow from master, not from this PR branch. If you modified the GitHub Action (e.g., added secrets or env vars), those changes won't take effect.

To test workflow changes, use the GitHub CLI or Actions UI instead:

gh workflow run eval-regression.yaml --repo HolmesGPT/holmesgpt --ref claude/streaming-timing-events-0sy5u -f markers=regression

Option 1: Comment on this PR with /eval:

/eval
markers: regression

Or with more options (one per line):

/eval
model: gpt-4o
markers: regression
filter: 09_crashpod
iterations: 5

Run evals on a different branch (e.g., master) for comparison:

/eval
branch: master
markers: regression
Option Description
model Model(s) to test (default: same as automatic runs)
markers Pytest markers (no default - runs all tests!)
filter Pytest -k filter (use /list to see valid eval names)
iterations Number of runs, max 10
branch Run evals on a different branch (for cross-branch comparison)

Quick re-run: Use /last to re-run the most recent /eval on this PR with the same parameters.

Option 2: Trigger via GitHub Actions UI → "Run workflow"

🏷️ Valid markers

benchmark, chain-of-causation, compaction, context_window, coralogix, counting, database, datadog, datetime, easy, embeds, grafana-dashboard, hard, kafka, kubernetes, leaked-information, logs, loki, medium, metrics, network, newrelic, no-cicd, numerical, one-test, port-forward, prometheus, question-answer, regression, runbooks, slackbot, storage, toolset-limitation, traces, transparency


Commands: /eval · /last · /list

Resolved conflicts in holmes/utils/stream.py by:
- Keeping timing tracking infrastructure (TimingTracker, TimingEvent classes)
- Adopting master's reorganized import structure
- Adding time import for timing functionality
- Maintaining all timing-related function signatures
@github-actions

github-actions Bot commented Jan 3, 2026 •

Copy link
Copy Markdown
Contributor

📂 Previous Runs

📜 Run @ 534e847 (#20679800790)

✅ Results of HolmesGPT evals

Automatically triggered by commit 534e847 on branch claude/streaming-timing-events-0sy5u

View workflow logs

Results of HolmesGPT evals

  • ask_holmes: 9/9 test cases were successful, 0 regressions
Status Test case Time Turns Tools Cost
✅ 09_crashpod 26.8s ↓19% 5 11 $0.1504
✅ 101_loki_historical_logs_pod_deleted 60.5s ↑13% 10 24 $0.2767
✅ 111_pod_names_contain_service 32.1s ↓22% 6 14 $0.1603
✅ 12_job_crashing 39.3s ↓16% 7 16 $0.1948
✅ 162_get_runbooks 36.9s ↓28% 6 14 $0.1840
✅ 176_network_policy_blocking_traffic_no_runbooks 30.0s ↓28% 5 12 $0.1548
✅ 24_misconfigured_pvc 30.4s ↓16% 6 15 $0.1583
✅ 43_current_datetime_from_prompt 3.2s ↓11% 1 — $0.0621
✅ 61_exact_match_counting 9.7s ↓13% 3 3 $0.0860
Total 29.9s avg 5.4 avg 13.6 avg $1.4274

Time/Cost columns show % change vs historical average (↑slower/costlier, ↓faster/cheaper). Changes under 10% shown as ±0%.

Historical Comparison Details

Filter: excluding branch 'claude/streaming-timing-events-0sy5u'

Status: Success - 24 test/model combinations loaded

Experiments compared (30):

Comparison indicators:

  • ±0% — diff under 10% (within noise threshold)
  • ↑N%/↓N% — diff 10-25%
  • ↑N%/↓N% — diff over 25% (significant)
📜 Run @ 123daf4 (#20678772736)

✅ Results of HolmesGPT evals

Automatically triggered by commit 123daf4 on branch claude/streaming-timing-events-0sy5u

View workflow logs

Results of HolmesGPT evals

  • ask_holmes: 9/9 test cases were successful, 0 regressions
Status Test case Time Turns Tools Cost
✅ 09_crashpod 28.1s ↓14% 5 11 $0.1473
✅ 101_loki_historical_logs_pod_deleted 46.1s ↓16% 8 15 $0.1999
✅ 111_pod_names_contain_service 36.9s ±0% 7 15 $0.1728
✅ 12_job_crashing 45.4s ±0% 9 17 $0.2194
✅ 162_get_runbooks 44.8s ↓11% 7 19 $0.2340
✅ 176_network_policy_blocking_traffic_no_runbooks 29.7s ↓26% 5 12 $0.1543
✅ 24_misconfigured_pvc 30.4s ↓15% 6 15 $0.1606
✅ 43_current_datetime_from_prompt 3.5s ±0% 1 — $0.0621
✅ 61_exact_match_counting 10.5s ±0% 3 3 $0.0860
Total 30.6s avg 5.7 avg 13.4 avg $1.4363

Time/Cost columns show % change vs historical average (↑slower/costlier, ↓faster/cheaper). Changes under 10% shown as ±0%.

Historical Comparison Details

Filter: excluding branch 'claude/streaming-timing-events-0sy5u'

Status: Success - 24 test/model combinations loaded

Experiments compared (30):

Comparison indicators:

  • ±0% — diff under 10% (within noise threshold)
  • ↑N%/↓N% — diff 10-25%
  • ↑N%/↓N% — diff over 25% (significant)

✅ Results of HolmesGPT evals

Automatically triggered by commit cdd79fc on branch claude/streaming-timing-events-0sy5u

View workflow logs

Results of HolmesGPT evals

  • ask_holmes: 9/9 test cases were successful, 0 regressions
Status Test case Time Turns Tools Cost
✅ 09_crashpod 29.2s ±0% 5 12 $0.0981
✅ 101_loki_historical_logs_pod_deleted 38.3s ↓22% 7 13 $0.1196
✅ 111_pod_names_contain_service 38.7s ±0% 7 15 $0.1283
✅ 12_job_crashing 39.4s ↓14% 7 15 $0.1286
✅ 162_get_runbooks 49.4s ±0% 8 19 $0.1921
✅ 176_network_policy_blocking_traffic_no_runbooks 39.3s ±0% 6 16 $0.1235
✅ 24_misconfigured_pvc 33.8s ±0% 6 17 $0.1117
✅ 43_current_datetime_from_prompt 3.7s ↑11% 1 — $0.0086
✅ 61_exact_match_counting 10.9s ±0% 3 3 $0.0326
Total 31.4s avg 5.6 avg 13.8 avg $0.9431

Time/Cost columns show % change vs historical average (↑slower/costlier, ↓faster/cheaper). Changes under 10% shown as ±0%.

Historical Comparison Details

Filter: excluding branch 'claude/streaming-timing-events-0sy5u'

Status: Success - 21 test/model combinations loaded

Experiments compared (30):

Comparison indicators:

  • ±0% — diff under 10% (within noise threshold)
  • ↑N%/↓N% — diff 10-25%
  • ↑N%/↓N% — diff over 25% (significant)
📖 Legend
Icon Meaning
✅ The test was successful
➖ The test was skipped
⚠️ The test failed but is known to be flaky or known to fail
🚧 The test had a setup failure (not a code regression)
🔧 The test failed due to mock data issues (not a code regression)
🚫 The test was throttled by API rate limits/overload
❌ The test failed and should be fixed before merging the PR
🔄 Re-run evals manually

⚠️ Warning: /eval comments always run using the workflow from master, not from this PR branch. If you modified the GitHub Action (e.g., added secrets or env vars), those changes won't take effect.

To test workflow changes, use the GitHub CLI or Actions UI instead:

gh workflow run eval-regression.yaml --repo HolmesGPT/holmesgpt --ref claude/streaming-timing-events-0sy5u -f markers=regression -f filter=

Option 1: Comment on this PR with /eval:

/eval
markers: regression

Or with more options (one per line):

/eval
model: gpt-4o
markers: regression
filter: 09_crashpod
iterations: 5

Run evals on a different branch (e.g., master) for comparison:

/eval
branch: master
markers: regression
Option Description
model Model(s) to test (default: same as automatic runs)
markers Pytest markers (no default - runs all tests!)
filter Pytest -k filter (use /list to see valid eval names)
iterations Number of runs, max 10
branch Run evals on a different branch (for cross-branch comparison)

Quick re-run: Use /rerun to re-run the most recent /eval on this PR with the same parameters.

Option 2: Trigger via GitHub Actions UI → "Run workflow"

🏷️ Valid markers

benchmark, chain-of-causation, compaction, context_window, coralogix, counting, database, datadog, datetime, easy, embeds, grafana-dashboard, hard, kafka, kubernetes, leaked-information, logs, loki, medium, metrics, network, newrelic, no-cicd, numerical, one-test, port-forward, prometheus, question-answer, regression, runbooks, slackbot, storage, toolset-limitation, traces, transparency


Commands: /eval · /rerun · /list

CLI: gh workflow run eval-regression.yaml --repo HolmesGPT/holmesgpt --ref claude/streaming-timing-events-0sy5u -f markers=regression -f filter=

Implements detailed timing instrumentation to diagnose why /api/chat is slower
than direct eval tests with AWS Bedrock Claude.

New timing events tracked:
- config_load_start/end: Toolset initialization overhead
- dal_operation: Database call durations
- message_build_start/end: Message construction time
- prompt_construction_start/end: Prompt building with runbooks
- context_limiting_start/end: Context window truncation overhead

Added PERFORMANCE_DIAGNOSTIC_GUIDE.md with:
- 10 theories about potential slowness causes
- Specific measurements to check for each theory
- Predictions and patterns to look for
- Expected values and benchmarks
- Fixes for each identified issue
- Example analysis script
- Quick diagnostic checklist

Each theory includes:
1. Hypothesis about the root cause
2. Specific timing events to examine
3. Predicted patterns if theory is correct
4. Expected duration ranges
5. Recommended fixes

This enables data-driven performance optimization by comparing timing
events between chat API and eval flows to identify bottlenecks.

@coderabbitai coderabbitai 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.

Actionable comments posted: 0

🧹 Nitpick comments (2)
server.py (1)

357-393: Minor optimization: avoid unconditional timestamp capture when timing is disabled.

Lines 371-374 capture dal_start = time.time() unconditionally but only use it when timing_tracker is not None. Consider moving the timestamp capture inside the if timing_tracker: guard to avoid unnecessary work when streaming is disabled.

🔎 Proposed refactor
-        # Track DAL operations
-        dal_start = time.time()
         global_instructions = dal.get_global_instructions_for_account()
         if timing_tracker:
+            dal_start = time.time()
             timing_tracker.record_dal_operation("get_global_instructions", (time.time() - dal_start) * 1000)

Note: This suggestion assumes the DAL operation is fast enough that capturing the timestamp before and after when timing_tracker exists will still give accurate measurements. If sub-millisecond precision is critical, the current approach is acceptable.

PERFORMANCE_DIAGNOSTIC_GUIDE.md (1)

1-444: Consider adding language specifiers to fenced code blocks for clarity.

The diagnostic guide is comprehensive and well-structured. However, several fenced code blocks (lines 46, 76, 102, 130, 157, 185, 217, 244, 272, 299, 342) lack language specifiers, which triggers markdownlint warnings and reduces clarity for readers.

Based on static analysis hints.

Example fixes

For pseudo-code or example output blocks, add a language specifier like text or plaintext:

-```
+```text
 Look for: llm_call_start → llm_call_end duration
 Compare: Chat API vs Eval for the SAME model call

For shell commands:
```diff
-```
+```bash
 # In eval environment
 time curl https://bedrock.amazonaws.com/...

</details>

</blockquote></details>

</blockquote></details>

<details>
<summary>📜 Review details</summary>

**Configuration used**: Organization UI

**Review profile**: CHILL

**Plan**: Pro

<details>
<summary>📥 Commits</summary>

Reviewing files that changed from the base of the PR and between 3221475288301cef4b8ef40c35e034fd19d7e5af and 534e84771ec1905027032c631b9a3d89e57f37cf.

</details>

<details>
<summary>📒 Files selected for processing (4)</summary>

* `PERFORMANCE_DIAGNOSTIC_GUIDE.md`
* `holmes/core/tool_calling_llm.py`
* `holmes/utils/stream.py`
* `server.py`

</details>

<details>
<summary>🧰 Additional context used</summary>

<details>
<summary>📓 Path-based instructions (1)</summary>

<details>
<summary>**/*.py</summary>


**📄 CodeRabbit inference engine (CLAUDE.md)**

> `**/*.py`: Use Ruff for formatting and linting (configured in pyproject.toml)
> Type hints required (mypy configuration in pyproject.toml)
> ALWAYS place Python imports at the top of the file, not inside functions or methods

Files:
- `holmes/utils/stream.py`
- `server.py`
- `holmes/core/tool_calling_llm.py`

</details>

</details><details>
<summary>🧬 Code graph analysis (2)</summary>

<details>
<summary>holmes/utils/stream.py (3)</summary><blockquote>

<details>
<summary>holmes/utils/cache.py (1)</summary>

* `default` (9-12)

</details>
<details>
<summary>holmes/plugins/toolsets/grafana/trace_parser.py (1)</summary>

* `duration_ms` (22-26)

</details>
<details>
<summary>holmes/core/tool_calling_llm.py (1)</summary>

* `call_stream` (722-998)

</details>

</blockquote></details>
<details>
<summary>server.py (4)</summary><blockquote>

<details>
<summary>holmes/utils/stream.py (3)</summary>

* `stream_investigate_formatter` (175-208)
* `stream_chat_formatter` (211-254)
* `TimingTracker` (43-144)

</details>
<details>
<summary>holmes/core/tool_calling_llm.py (1)</summary>

* `call_stream` (722-998)

</details>
<details>
<summary>holmes/config.py (3)</summary>

* `get_runbook_catalog` (228-232)
* `create_toolcalling_llm` (315-326)
* `dal` (123-126)

</details>
<details>
<summary>holmes/core/supabase_dal.py (2)</summary>

* `get_runbook_catalog` (515-544)
* `get_global_instructions_for_account` (621-640)

</details>

</blockquote></details>

</details><details>
<summary>🪛 LanguageTool</summary>

<details>
<summary>PERFORMANCE_DIAGNOSTIC_GUIDE.md</summary>

[grammar] ~89-~89: Ensure spelling is correct
Context: ...te: 50-150ms (15-25 toolsets) - Slow: > 150ms (30+ toolsets or complex initialization...

(QB_NEW_EN_ORTHOGRAPHY_ERROR_IDS_1)

---

[grammar] ~136-~136: Ensure spelling is correct
Context: ...rediction**: - If this is the issue: 20-100ms for complex prompts - Expected pattern:...

(QB_NEW_EN_ORTHOGRAPHY_ERROR_IDS_1)

---

[grammar] ~163-~163: Ensure spelling is correct
Context: ...rediction**: - If this is the issue: 50-300ms per iteration when compaction happens -...

(QB_NEW_EN_ORTHOGRAPHY_ERROR_IDS_1)

---

[grammar] ~191-~191: Ensure spelling is correct
Context: ...rediction**: - If this is the issue: 20-100ms extra per tool call - Expected pattern:...

(QB_NEW_EN_ORTHOGRAPHY_ERROR_IDS_1)

---

[grammar] ~203-~203: Ensure spelling is correct
Context: ...ms for medium responses (10-100KB) - 50-200ms for large responses (> 100KB)  **Fix if...

(QB_NEW_EN_ORTHOGRAPHY_ERROR_IDS_1)

---

[grammar] ~283-~283: Ensure spelling is correct
Context: ... **Typical overhead**: - SSE framing: < 5ms per message - JSON serialization: < 10m...

(QB_NEW_EN_ORTHOGRAPHY_ERROR_IDS_1)

---

[grammar] ~306-~306: Ensure spelling is correct
Context: ...rediction**: - If this is the issue: 20-100ms per LLM call - Expected pattern: Consis...

(QB_NEW_EN_ORTHOGRAPHY_ERROR_IDS_1)

---

[grammar] ~308-~308: Ensure spelling is correct
Context: ...ll see: All `llm_call` durations are 50-150ms longer  **LiteLLM overhead sources**: -...

(QB_NEW_EN_ORTHOGRAPHY_ERROR_IDS_1)

---

[grammar] ~308-~308: Ensure spelling is correct
Context: ...`llm_call` durations are 50-150ms longer  **LiteLLM overhead sources**: - Request tr...

(QB_NEW_EN_ORTHOGRAPHY_ERROR_IDS_1)

</details>

</details>
<details>
<summary>🪛 markdownlint-cli2 (0.18.1)</summary>

<details>
<summary>PERFORMANCE_DIAGNOSTIC_GUIDE.md</summary>

46-46: Fenced code blocks should have a language specified

(MD040, fenced-code-language)

---

76-76: Fenced code blocks should have a language specified

(MD040, fenced-code-language)

---

102-102: Fenced code blocks should have a language specified

(MD040, fenced-code-language)

---

130-130: Fenced code blocks should have a language specified

(MD040, fenced-code-language)

---

157-157: Fenced code blocks should have a language specified

(MD040, fenced-code-language)

---

185-185: Fenced code blocks should have a language specified

(MD040, fenced-code-language)

---

217-217: Fenced code blocks should have a language specified

(MD040, fenced-code-language)

---

244-244: Fenced code blocks should have a language specified

(MD040, fenced-code-language)

---

272-272: Fenced code blocks should have a language specified

(MD040, fenced-code-language)

---

299-299: Fenced code blocks should have a language specified

(MD040, fenced-code-language)

---

342-342: Fenced code blocks should have a language specified

(MD040, fenced-code-language)

</details>

</details>

</details>

<details>
<summary>⏰ Context from checks skipped due to timeout of 90000ms. You can increase the timeout in your CodeRabbit configuration to a maximum of 15 minutes (900000ms). (4)</summary>

* GitHub Check: llm_evals
* GitHub Check: build (3.11)
* GitHub Check: build (3.12)
* GitHub Check: build (3.10)

</details>

<details>
<summary>🔇 Additional comments (13)</summary><blockquote>

<details>
<summary>server.py (3)</summary><blockquote>

`31-31`: **LGTM!**

The `TimingTracker` import is correctly placed at the top of the file with other imports, in accordance with the coding guidelines.

---

`190-204`: **LGTM!**

Clean implementation: the `TimingTracker` is instantiated once and consistently passed to both `ai.call_stream` and `stream_investigate_formatter`, ensuring timing data is captured across the entire request lifecycle.

---

`418-431`: **LGTM!**

The timing tracker is consistently propagated through both `ai.call_stream` and `stream_chat_formatter`, maintaining the same pattern established in the `/api/stream/investigate` endpoint.

</blockquote></details>
<details>
<summary>holmes/core/tool_calling_llm.py (4)</summary><blockquote>

`819-827`: **LGTM!**

Adding `from e` to the exception raise preserves the original exception chain, improving debuggability. This is a best practice for exception handling in Python.

---

`767-784`: **LGTM!**

The context window limiting timing correctly wraps the operation and extracts relevant metadata (token counts before/after compaction) for diagnostic purposes.

---

`797-813`: **LGTM!**

LLM call timing correctly instruments the completion call with model and iteration metadata, enabling per-iteration performance analysis as described in the diagnostic guide.

---

`891-925`: **LGTM!**

The `futures_tool_info` dictionary correctly maps each future to its tool metadata, enabling accurate timing correlation when futures complete out of order. This pattern is essential for concurrent tool execution timing.

Note: The check `future in futures_tool_info` on line 919 is technically redundant (if `timing_tracker` exists, the future will always be in the dict), but serves as defensive programming.

</blockquote></details>
<details>
<summary>holmes/utils/stream.py (6)</summary><blockquote>

`3-3`: **LGTM!**

The `time` import is correctly placed at the top of the file, following the coding guidelines.

---

`29-41`: **LGTM!**

The `TimingEvent` model and `StreamMessage.timing` field are well-defined with proper type hints and Pydantic validation.

---

`43-145`: **LGTM!**

The `TimingTracker` class is well-implemented with proper time calculations and event recording. The stringification of metadata values (iterations, counts, etc.) ensures consistent JSON serialization across all event types.

Note: This class is not thread-safe, but that's acceptable since each streaming request instantiates its own tracker instance.

---

`147-153`: **LGTM!**

The `timing_info` parameter is cleanly integrated into `create_sse_message`, allowing timing data to be embedded in SSE payloads when available.

---

`175-208`: **LGTM!**

The `stream_investigate_formatter` correctly integrates timing tracking by retrieving current timing info for each message and embedding it in the SSE payload. The pattern gracefully handles cases where timing tracking is disabled.

---

`211-254`: **LGTM!**

The `stream_chat_formatter` follows the same clean pattern as the investigate formatter, consistently embedding timing information in all streamed messages (ANSWER_END, APPROVAL_REQUIRED, and generic events).

</blockquote></details>

</blockquote></details>

</details>

<!-- This is an auto-generated comment by CodeRabbit for review status -->

RunbookCatalog doesn't have __len__, need to use len(runbooks.catalog) instead.

Fixes error: object of type 'RunbookCatalog' has no len()

@coderabbitai coderabbitai 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.

Actionable comments posted: 0

🧹 Nitpick comments (2)
server.py (2)

370-374: Consider moving dal_start inside the timing check for consistency.

The time.time() call on line 371 executes even when timing_tracker is None. While the performance impact is negligible, moving it inside the conditional would be more consistent with the guarding pattern used elsewhere.

🔎 Suggested refactor
-        # Track DAL operations
-        dal_start = time.time()
         global_instructions = dal.get_global_instructions_for_account()
         if timing_tracker:
+            dal_start = time.time()
             timing_tracker.record_dal_operation("get_global_instructions", (time.time() - dal_start) * 1000)

Wait, this won't work because we need dal_start before the operation. Better approach:

         # Track DAL operations
+        if timing_tracker:
+            dal_start = time.time()
-        dal_start = time.time()
         global_instructions = dal.get_global_instructions_for_account()
         if timing_tracker:
             timing_tracker.record_dal_operation("get_global_instructions", (time.time() - dal_start) * 1000)

377-393: Consider whether both timing events are needed for the same operation.

Both message_build and prompt_construction timing events are started and ended at the same points, measuring the identical time span of the build_chat_messages call. While they record different metadata (num_messages vs num_runbooks), this creates two timing events for what appears to be a single operation.

If these are meant to provide different perspectives on the same operation, the current implementation is fine. Otherwise, you might consider whether one event with combined metadata would be clearer.

📜 Review details

Configuration used: Organization UI

Review profile: CHILL

Plan: Pro

📥 Commits

Reviewing files that changed from the base of the PR and between 534e847 and cdd79fc.

📒 Files selected for processing (1)
  • server.py
🧰 Additional context used
📓 Path-based instructions (1)
**/*.py

📄 CodeRabbit inference engine (CLAUDE.md)

**/*.py: Use Ruff for formatting and linting (configured in pyproject.toml)
Type hints required (mypy configuration in pyproject.toml)
ALWAYS place Python imports at the top of the file, not inside functions or methods

Files:

  • server.py
🧬 Code graph analysis (1)
server.py (2)
holmes/utils/stream.py (3)
  • stream_investigate_formatter (175-208)
  • stream_chat_formatter (211-254)
  • TimingTracker (43-144)
holmes/core/tool_calling_llm.py (1)
  • call_stream (722-998)
⏰ Context from checks skipped due to timeout of 90000ms. You can increase the timeout in your CodeRabbit configuration to a maximum of 15 minutes (900000ms). (4)
  • GitHub Check: llm_evals
  • GitHub Check: build (3.10)
  • GitHub Check: build (3.12)
  • GitHub Check: build (3.11)
🔇 Additional comments (5)
server.py (5)

31-31: LGTM!

The import is correctly placed at the top of the file as required by the coding guidelines.


190-203: LGTM!

The timing tracker is properly initialized and correctly propagated through both the LLM streaming call and the formatter. This follows the pattern established in the TimingTracker API.


357-358: LGTM!

The conditional initialization ensures timing tracking is only performed for streaming requests, which is the correct behavior since timing events are only emitted in SSE messages.


361-368: LGTM!

The config load timing correctly brackets the runbook catalog retrieval and LLM initialization, with appropriate metadata about the number of toolsets.


418-431: LGTM!

The streaming response path correctly propagates the timing tracker through both the LLM streaming call and the formatter, along with the follow-up actions. This matches the pattern used in stream_investigate_issues.

@aantn aantn changed the title Add comprehensive timing tracking to streaming responses Track timing on streaming /chat requests Jan 5, 2026

This branch has not been deployed

No deployments
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