Skip to content

[chore] Report completed storage requests from the latency histogram #192

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
0oshowero0 merged 1 commit into from
Oct 13, 2026
Merged

[chore] Report completed storage requests from the latency histogram #192

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
17 changes: 12 additions & 5 deletions docs/metrics.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -148,10 +148,13 @@ Steps:

### Storage Request-Loss Diagnostics (collected via ZMQ, exposed on controller)

Arrivals are counted when the worker decodes a request, while `tq_storage_request_ops` only
advances once one completes, so a sustained gap between them means requests are arriving and
not finishing. The counters are cumulative per operation and carry no request identity, so
they characterise a unit, not any individual request.
Arrivals are counted when the worker decodes a request, and `tq_storage_request_ops` when its
handler returns or raises. The same worker answers the collector, so these counters are only
reported between requests: they cannot show a handler that is still running, and a unit stuck
in one stops answering, leaving its gauges at their last values (the timeout diagnosis then
reports `unit_not_serving`). To see handlers in progress, use the storage unit's own endpoint
below. The counters are cumulative per operation and carry no request identity, so they
characterise a unit, not any individual request.

| Metric | Type | Labels | Description |
|--------|------|--------|-------------|
Expand Down Expand Up @@ -183,10 +186,14 @@ prevented every drop in that window.
| Metric | Type | Labels | Description |
|--------|------|--------|-------------|
| `tq_storage_request_duration_seconds` | Histogram | `op_type` | Request latency (buckets: 1ms–5s) |
| `tq_storage_request_total` | Counter | `op_type` | Total requests processed |
| `tq_storage_request_total` | Counter | `op_type` | Requests whose handler has started |
| `tq_storage_request_errors_total` | Counter | `op_type` | Total request errors |
| `tq_storage_request_samples_total` | Counter | `op_type` | Total samples processed per operation |

This endpoint is served by its own thread rather than the worker, so `tq_storage_request_total`
minus `tq_storage_request_duration_seconds_count` (observed when a handler returns or raises)
gives the handlers still running, even while the worker is stuck.

> **Note on naming**: The ZMQ-collected gauges on the controller avoid all Prometheus reserved suffixes (`_total`, `_bucket`, `_sum`, `_count`, `_info`, `_created`) and the reserved `le` label to prevent type metadata conflicts that break `label_values()` queries. P50/P99 are computed on the storage unit side and sent as pre-calculated values. The storage unit's own endpoint uses standard Counter/Histogram naming conventions.

## Grafana Dashboard
Expand Down
5 changes: 3 additions & 2 deletions transfer_queue/storage/simple_storage.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1397,13 +1397,14 @@ def _handle_get_metrics(self) -> ZMQMessage:
for op_type in ("PUT_DATA", "UPDATE_DATA", "GET_DATA", "CLEAR_DATA", "DUMP_ROWS", "LOAD_ROWS"):
try:
hist = self._metrics.request_duration.labels(op_type=op_type)
counter = self._metrics.request_total.labels(op_type=op_type)
duration_sum = hist._sum.get()
# Build cumulative counts once, reuse for total and quantiles
cumulative_counts = self._cumulative_bucket_counts(hist)
duration_count = cumulative_counts[-1] if cumulative_counts else 0
op_stats[op_type] = {
"request_count": counter._value.get(),
# Observed when the handler returns or raises. request_total counts entry and
# agrees only because this worker answers GET_METRICS after each handler.
"request_count": duration_count,

@chatgpt-codex-connector chatgpt-codex-connector Bot Oct 13, 2026

Copy link
Copy Markdown

Choose a reason for hiding this comment

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

P2 Badge Serve in-flight metrics outside the serialized worker

When a real storage handler stalls, this completion value cannot be queried concurrently: _worker_routine synchronously runs the single _process_one_worker_request path (transfer_queue/storage/simple_storage.py:1048-1067), and GET_METRICS is another branch of that same dispatcher at lines 1118-1119. The collector's metrics request therefore waits behind the stuck request (and times out), while after the handler returns the histogram has already been observed, so tq_storage_request_ops never exposes the intended arrival/completion gap. The new test only passes because it calls _handle_get_metrics() directly from a second thread, which the supported ZMQ path cannot do; this snapshot needs an independently serviced path and a test through the real dispatcher.

AGENTS.md reference: AGENTS.md:L17-L18

Useful? React with 👍 / 👎.

@0oshowero0 0oshowero0 Oct 13, 2026

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

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

Agreed. A storage unit has one worker, and it answers GET_METRICS only after the previous handler has returned. Through the supported path, request_total and the histogram count are therefore always equal when read. A stuck handler shows up as an unanswered collector query or probe (unit_not_serving), not as a gap.

I've narrowed the PR to match (4146d6d):

  • Framing: the change now only makes request_count mean "completed" by construction, from the same histogram that latency_avg uses, and it states that no reported value changes.
  • Docs: docs/metrics.md claimed that the collected gap reveals unfinished requests. That claim is now removed.
  • Test: it stays as a contract test for the field, and its docstring now says that this interleaving is not reachable through the worker today.

I don't think a separate metrics path is needed. The storage unit's own endpoint is served by its own thread, so handlers still in progress are already visible there as tq_storage_request_total minus tq_storage_request_duration_seconds_count; the updated doc now points there.

@0oshowero0 0oshowero0 Oct 13, 2026

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

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

Follow-up: I dropped the test in 4a223d5. It could only tell the old and new source apart by reading the metrics while a handler is still running, which is the interleaving this worker never produces, so it guarded nothing a user can observe. The PR is now the field source plus the docs/metrics.md correction.

"latency_avg": duration_sum / duration_count if duration_count > 0 else 0,
"latency_p50": self._quantile_from_cumulative(hist, cumulative_counts, 0.50),
"latency_p99": self._quantile_from_cumulative(hist, cumulative_counts, 0.99),
Expand Down
Loading