Measure actual queue latency separately from request execution #60

New issue

Closed

opened 2026-07-26 05:22:33 +00:00 by coilyco-ops · 0 comments

coilyco-ops commented

2026-07-26 05:22:33 +00:00

Owner

Problem

The queue.wait trace span does not measure time spent waiting for a worker. It starts after the job is enqueued and remains open until the request future completes, so it includes queue delay, resilience dispatch, the upstream model call, and response completion.

This makes SigNoZ report model execution time as queue latency and can produce false queue-saturation diagnoses.

Observed evidence

A read-only SigNoZ review of two successful agent-proxy requests found:

One request.chat span lasted about 14.445 seconds while upstream.chat lasted about 14.443 seconds.
One request.chat span lasted about 2.107 seconds while upstream.chat lasted about 2.105 seconds.
The corresponding queue.wait spans lasted about 14.445 and 2.107 seconds.
Neither request retried, fell back, or failed.

The evidence indicates that upstream execution dominated both requests. It does not indicate that either request waited that long in the queue.

Cause

app/queue.py starts queue.wait around await future. The worker completes that future only after dispatch and upstream execution finish.

Desired behavior

Agent Proxy records actual enqueue-to-dequeue latency independently from execution latency.

A suitable shape is:

Record an enqueue timestamp on the job.
End a queue.wait span, or record a queue-wait histogram, when a worker dequeues the job.
Keep dispatch, resilience attempts, and upstream calls in their existing spans.
Preserve request correlation and the existing safe metadata attributes.

Acceptance

A deliberately blocked worker produces queue latency matching enqueue-to-dequeue time.
A slow upstream call with an idle worker produces low queue latency and high upstream.chat latency.
Queue rejection remains separately observable.
Tests assert span or metric timing semantics, not only attribute propagation.
Operational telemetry contains no prompt, response, or raw customer payload.

## Problem The `queue.wait` trace span does not measure time spent waiting for a worker. It starts after the job is enqueued and remains open until the request future completes, so it includes queue delay, resilience dispatch, the upstream model call, and response completion. This makes SigNoZ report model execution time as queue latency and can produce false queue-saturation diagnoses. ## Observed evidence A read-only SigNoZ review of two successful `agent-proxy` requests found: * One `request.chat` span lasted about 14.445 seconds while `upstream.chat` lasted about 14.443 seconds. * One `request.chat` span lasted about 2.107 seconds while `upstream.chat` lasted about 2.105 seconds. * The corresponding `queue.wait` spans lasted about 14.445 and 2.107 seconds. * Neither request retried, fell back, or failed. The evidence indicates that upstream execution dominated both requests. It does not indicate that either request waited that long in the queue. ## Cause `app/queue.py` starts `queue.wait` around `await future`. The worker completes that future only after dispatch and upstream execution finish. ## Desired behavior Agent Proxy records actual enqueue-to-dequeue latency independently from execution latency. A suitable shape is: * Record an enqueue timestamp on the job. * End a `queue.wait` span, or record a queue-wait histogram, when a worker dequeues the job. * Keep dispatch, resilience attempts, and upstream calls in their existing spans. * Preserve request correlation and the existing safe metadata attributes. ## Acceptance * A deliberately blocked worker produces queue latency matching enqueue-to-dequeue time. * A slow upstream call with an idle worker produces low queue latency and high `upstream.chat` latency. * Queue rejection remains separately observable. * Tests assert span or metric timing semantics, not only attribute propagation. * Operational telemetry contains no prompt, response, or raw customer payload.

coilyco-ops

2026-07-29 03:44:46 +00:00

closed this issue
added the
autonomy
async-consult

priority
P4
labels

No milestone

No project

No assignees

1 participant

Notifications

Due date

The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set

Reference

coilyco-flight-deck/agent-proxy#60

No description provided.

Rows
Columns