Add EPP request/response processing latency metrics#1658
Conversation
There was a problem hiding this comment.
Pull request overview
Note
Copilot was unable to run its full agentic suite in this review.
Adds end-to-end latency instrumentation for EPP request/response processing, including new Prometheus histograms and integration points in request orchestration and streaming response handling.
Changes:
- Instrument request processing latency in
Director.HandleRequest, subtracting flow-control admission time. - Accumulate and record response processing latency across response header/body handlers (streaming and non-streaming).
- Register/reset new histograms and add golden-file tests for both metrics.
Reviewed changes
Copilot reviewed 7 out of 7 changed files in this pull request and generated 4 comments.
Show a summary per file
| File | Description |
|---|---|
| pkg/epp/requestcontrol/director.go | Adds request processing latency timing and subtracts admission duration. |
| pkg/epp/handlers/server.go | Accumulates response handler processing time and records a histogram observation at response completion. |
| pkg/epp/metrics/llm_d_router_metrics.go | Defines new Prometheus histogram vectors for request/response processing durations. |
| pkg/epp/metrics/metrics.go | Registers/resets new histograms and exposes recording helper functions. |
| pkg/epp/metrics/metrics_test.go | Adds tests that compare gathered metrics to testdata fixtures. |
| pkg/epp/metrics/testdata/llm_d_request_processing_duration_seconds_metric | Golden output for request processing histogram. |
| pkg/epp/metrics/testdata/llm_d_response_processing_duration_seconds_metric | Golden output for response processing histogram. |
| start := time.Now() | ||
| var admissionWait time.Duration | ||
| // request_processing_duration captures EPP's own processing cost, so the | ||
| // flow-control admission wait (tracked separately by | ||
| // flow_control_request_queue_duration_seconds) is subtracted out. | ||
| defer func() { metrics.RecordRequestProcessingLatency(time.Since(start) - admissionWait) }() |
| admitStart := time.Now() | ||
| admitErr := d.admissionController.Admit(ctx, reqCtx, priority) | ||
| admissionWait = time.Since(admitStart) |
| // request_processing_duration captures EPP's own processing cost, so the | ||
| // flow-control admission wait (tracked separately by | ||
| // flow_control_request_queue_duration_seconds) is subtracted out. | ||
| defer func() { metrics.RecordRequestProcessingLatency(time.Since(start) - admissionWait) }() |
| reqCtx.responseProcessingDuration += time.Since(respBodyStart) | ||
| if endOfStream { | ||
| metrics.RecordResponseProcessingLatency(reqCtx.responseProcessingDuration) | ||
| } |
6d42111 to
0682683
Compare
|
@liu-cong can you please review this PR |
Sorry for the delay. I am focusing on the release right now. Will try to get to this later this week if everything goes well on the release. |
Sure. Thanks @liu-cong |
|
This PR is marked as stale after 21d of inactivity. After an additional 14d of inactivity (7d to become rotten, then 7d more), it will be closed. To prevent this PR from being closed, add a comment or remove the |
elevran
left a comment
There was a problem hiding this comment.
Two CI failures on this PR. The test job fails because the new unit tests assert the wrong subsystem constant.
The PR title and the release-note block both also advertise the wrong metric name and must be fixed.
Release-note should read:
Add `llm_d_epp_request_processing_duration_seconds` and `llm_d_epp_response_processing_duration_seconds` metrics measuring EPP request and response processing overhead.
Can be done here or in a follow up PR (please open a tracking issue if deferring):
docs/metrics.mddoes not list the new metrics. Since the PR description treats them as user-facing, a one-line entry under the existingllm_d_epp_*section would keep the catalog accurate.- The e2e-gaie preset in
test/e2e/epp/utils_test.go:260-289does not assert these metrics either, so they are not exercised by the e2e-gaie suite. Worth a follow-up to add them to the preset.
| t.Fatal(err) | ||
| } | ||
| defer want.Close() | ||
| if err := promtestutil.GatherAndCompare(metrics.Registry, want, "llm_d_router_epp_request_processing_duration_seconds"); err != nil { |
There was a problem hiding this comment.
This assertion looks for the wrong metric name. LLMDRouterEndpointPickerSubsystem is "llm_d_epp" (line 28 of llm_d_router_metrics.go), so the histogram is emitted as llm_d_epp_request_processing_duration_seconds, matching the rest of the package (llm_d_epp_request_total, llm_d_epp_request_error_total, etc.). Drop the _router_ segment here and in the testdata filename + fixture # HELP/# TYPE/metric lines.
| if err := promtestutil.GatherAndCompare(metrics.Registry, want, "llm_d_router_epp_request_processing_duration_seconds"); err != nil { | |
| if err := promtestutil.GatherAndCompare(metrics.Registry, want, "llm_d_epp_request_processing_duration_seconds"); err != nil { |
| t.Fatal(err) | ||
| } | ||
| defer want.Close() | ||
| if err := promtestutil.GatherAndCompare(metrics.Registry, want, "llm_d_router_epp_response_processing_duration_seconds"); err != nil { |
There was a problem hiding this comment.
Same off-by-one as the previous comment: drop _router_ so the assertion matches the emitted name llm_d_epp_response_processing_duration_seconds. Also rename the testdata file and update its contents.
| if err := promtestutil.GatherAndCompare(metrics.Registry, want, "llm_d_router_epp_response_processing_duration_seconds"); err != nil { | |
| if err := promtestutil.GatherAndCompare(metrics.Registry, want, "llm_d_epp_response_processing_duration_seconds"); err != nil { |
|
Please be sure to fix the all relevant fields of the new metrics (names, Help text, unit tests, and the testdata fixtures) - they all use the wrong prefix, |
a9ed745 to
8bde1d2
Compare
8bde1d2 to
ac71d6b
Compare
ac71d6b to
c1011a2
Compare
c1011a2 to
f9bf0a8
Compare
|
Thanks @liu-cong. Two questions before I rewrite this. Request metric. Happy to move it to server.go, RequestReceivedTimestamp through the end of the RequestBody case. But that window swallows director.HandleRequest, so it swallows admission control too. Right now I subtract that (director.go#L304-L306) because under flow control Admit is EnqueueAndWait and the queue wait would dominate the histogram. Do you want it still excluded after the move, or just the raw span? If it stays excluded, I'd like to fix what Copilot caught while I'm in there. I subtract the whole Admit call, but LegacyAdmissionController.Admit doesn't queue at all, it just runs saturation detection. Flow control is off by default, so today we subtract real EPP work out of an EPP-overhead metric. I think the cleanest fix is Admit returning its own queue wait (zero for legacy). Can you please suggest Response metric. On #1553 you said accumulated sum makes sense for streaming, but the inline comments here describe a single elapsed span. I read that as: non-streaming becomes one span headers-to-finishResponse, streaming keeps the sum, since an elapsed span there would just re-measure generation time. Right? |
This is expected by the definition of this metric. The queue wait time only applies when queuing happens.
Yeah for streaming it's a bit complex, we will need to measure the sum of per-chunk EPP response processing latency. |
f6c98f8 to
5401f66
Compare
74907cc to
64d6565
Compare
64d6565 to
b078493
Compare
Signed-off-by: satyamg1620 <Satyam.Gupta.3@ibm.com>
Signed-off-by: satyamg1620 <Satyam.Gupta.3@ibm.com>
Signed-off-by: satyamg1620 <Satyam.Gupta.3@ibm.com>
Signed-off-by: satyamg1620 <Satyam.Gupta.3@ibm.com>
Signed-off-by: satyamg1620 <Satyam.Gupta.3@ibm.com>
b078493 to
93a9bc1
Compare
What type of PR is this?
/kind feature
What this PR does / why we need it:
Adds two EPP latency metrics from #1553 to expose EPP processing overhead:
llm_d_epp_request_processing_duration_seconds— from request receipt until the request body has been handled; includes admission control.llm_d_epp_response_processing_duration_seconds— per-chunk handler sum for streaming, header-to-completion span for non-streaming; excludes model-server generation time.Which issue(s) this PR fixes:
Fixes #1553
Release note (write
NONEif no user-facing change):