feat(obs): run + attempt latency histograms, configurable REFINE_TIMEOUT - #232
feat(obs): run + attempt latency histograms, configurable REFINE_TIMEOUT#232wanyiwang06 wants to merge 3 commits into
Conversation
… guard Batch 1 + S1 from Mininglamp-OSS#231. No new dependencies, no new endpoints. ## llmobs: add histogramVec, expose llm_call_duration_seconds The existing llm_call_duration_seconds_total is a cumulative sum, so the only statistic derivable from it is a mean. A mean over this workload describes no real request: refine calls are sub-second while long-context agent turns are documented at 60-100s. Mininglamp-OSS#220 explicitly defers the final LLM_TIMEOUT to per-scenario P95/P99, which needs bucket counts. Buckets are fixed at package scope (0.5s..300s) so paths stay comparable, and the series is labelled by path ONLY: bucket series multiply by len(buckets)+3, so a stray dimension is far more expensive here than on a counter. The counter is kept; this is additive. Hand-rolled to match the package's existing text-exposition registry -- see the package doc for why client_golang is not used here. ## service/llm: pass PerModelTimeout on the generic Call/CallStream paths llmfallback.Run's deadline-aware escalation only arms when it is told what one attempt costs: before a backoff it checks whether the remaining parent budget can still fit that sleep, the pending retry AND one full attempt on the next model, escalating early (SwitchReason budget_starved) when it cannot. agent/llm.go and CallWithTools already passed it; the two generic entry points did not, so every worker Map/Reduce and API refine call ran with the guard disabled -- spending the primary's whole retry budget and handing the fallback whatever remained. That is the starvation Mininglamp-OSS#220 §1 describes, and it was also unreportable: budget_starved could not be emitted on those paths at all. ## service/llm: tag the three untagged ReduceByPerson variants CallReduceByPerson, CallReduceByPersonWithModel and CallReduceByPersonStream did not call WithPath, so their metrics would land in path="unknown". None has a production caller today (only the ...StreamWithModel variant is wired, and it was already tagged), so this is pre-emptive: the next caller inherits correct attribution instead of silently polluting a bucket. ## handler: make the refine budget configurable (REFINE_TIMEOUT) Four call sites hardcoded a 90s parent context around a Run whose per-attempt budget is LLM_TIMEOUT (default 180s). A parent smaller than one attempt means no fallback model is ever reachable, so LLM_FALLBACK_MODELS is inert on refine. The default is deliberately unchanged at 90s -- raising it alters user-visible latency and the right value depends on the refine P95 this commit starts collecting. What changes is that it stops being welded into four call sites. ## Tests - exact cumulative bucket/_sum/_count values, including a 400s over-range sample that must still reach +Inf (a histogram that drops outliers hides precisely the tail these percentiles exist for) - a label-set assertion pinning {path,le} as the permitted set - concurrent observation, for the worker's parallel Map chunks - parseExposition taught to resolve _bucket/_sum/_count back to the base family, as a real scraper does Verification: CGO_LDFLAGS=-L/home/mlamp/.local/lib go test -race -count=1 ./... PASS CGO_LDFLAGS=-L/home/mlamp/.local/lib go vet ./... PASS git diff --check PASS Refs Mininglamp-OSS#231, Mininglamp-OSS#220
There was a problem hiding this comment.
Superseding review — REQUEST_CHANGES on 7ed3e73
yujiawei
left a comment
There was a problem hiding this comment.
Code Review — PR #232 (octo-smart-summary)
Reviewed at head 7ed3e73, against merge-base eb9e0e3. I checked the branch out and ran the suites locally (go1.26.5): go test -race -count=1 ./internal/llmobs/... ./internal/llmfallback/... ./internal/api/handler/... — all PASS.
The histogram is good work and I'd take it as-is. The problem is the other half of the PR: the two hunks that change runtime behaviour have no tests, and when you trace them through the call graph they do close to the opposite of what the description claims. Details below, with the probe I used to confirm.
1. Spec compliance
Result: not met.
Measured against this PR's own "Change" section:
| Stated change | Status |
|---|---|
internal/llmobs: add histogramVec, expose llm_call_duration_seconds |
Implemented as described |
Tag the three untagged ReduceByPerson variants |
Implemented; the "no production caller today" claim is correct (verified by grep — only CallReduceByPersonStreamWithModel is wired, at internal/worker/meta_processor.go:235, and it was already tagged) |
internal/api/handler: make the refine budget configurable |
Implemented, but incomplete — see 2.5 (undocumented) and 2.6 (no tests) |
internal/service/llm.go: pass PerModelTimeout on Call/CallStream — "Arms the deadline guard on worker Map/Reduce, and makes budget_starved reportable on those paths for the first time" |
Diverges. Both halves of that sentence are false. See 2.1 |
The divergence in the last row is the blocking one, and it is not a wording quibble — the same claim is now baked into a source comment at internal/service/llm.go:270-278, where it will be read as ground truth by whoever next debugs a fallback.
2. Code quality
Result: changes requested. Two P1, six P2.
P1-1 — PerModelTimeout is inert on worker Map/Reduce; the guard is still disarmed there
The guard is gated on the parent context having a deadline:
// internal/llmfallback/fallback.go:306-315
if hasNext && cfg.PerModelTimeout > 0 {
if dl, ok := ctx.Deadline(); ok {
remaining := time.Until(dl)
if remaining > delay && remaining < delay+2*cfg.PerModelTimeout {
return zero, TryNextModel, &budgetStarvedErr{...}Every worker entry point starts from context.Background() and propagates it unchanged:
internal/worker/processor.go:183,:253internal/worker/meta_processor.go:78internal/worker/personal_processor.go:623
A repo-wide grep for context.WithTimeout|context.WithDeadline (excluding tests) confirms there is no deadline anywhere between those roots and callWithPolicyAndModel. The repo's own docs already say so — CONFIGURATION.md:21: "Worker/API paths have no aggregate fallback deadline" — and so does issue #220 §2: "调用方也没有聚合 deadline".
I confirmed it against the real llmfallback.Run with a throwaway probe (two models, PerModelTimeout: 180s, MaxAttempts: 3, every attempt classified RetrySameModel):
parent = context.Background() → switch primary->fallback reason=retries_exhausted attempts=3
parent = context.WithTimeout(.., 90s) → switch primary->fallback reason=budget_starved attempts=1
So on worker_map / worker_reduce nothing changed, and budget_starved is still unemittable there — which is precisely the "diagnostic dead end" the description says this hunk removes. It is now worse than before the PR: an operator who queries llm_model_switch_total{path="worker_map",reason="budget_starved"} == 0 will read it as "starvation is not happening", when the true meaning is "the guard never ran". Before, at least the absence of PerModelTimeout in the config literal made that obvious at the call site.
One more thing worth correcting: the description attributes the worker gap to "the starvation #220 §1 describes." #220 §1 is about the agent path and AGENT_STEP_TIMEOUT — which already passed PerModelTimeout (internal/agent/llm.go:101). The worker gap is #220 §2, and what §2 asks for is an aggregate deadline bounded below the ~10-minute stuck scanner and the 20-minute lease, because the worst case there is ~18–27 minutes of retries causing duplicate dispatch. That risk is untouched here.
Fix — pick one:
- (a) Add the aggregate deadline #220 §2 asks for at the worker call sites.
PerModelTimeoutthen becomes meaningful and the description becomes true. This is the real fix, and probably its own PR. - (b) Keep the one-line change but scope the claim to
api_refine, and delete the worker sentence from both the PR body andinternal/service/llm.go:270-278.
Either way, please don't ship a comment asserting a guard is armed on a path where it provably is not.
P1-2 — On api_refine, the shipped defaults make the guard fire on every first retry
With REFINE_TIMEOUT defaulting to 90s (internal/api/handler/refine_budget.go:29) and PerModelTimeout = c.timeout = LLM_TIMEOUT = 180s (internal/config/config.go:210, internal/service/llm.go:85), the guard condition is:
remaining < delay + 2*cfg.PerModelTimeout // ≤90 < 1 + 360 → always trueSo whenever LLM_FALLBACK_MODELS is non-empty and the primary hits any transient 429/5xx/transport error, the primary is abandoned after one attempt with budget_starved, instead of retrying three times. Concretely: primary returns a single transient 503 and then recovers, fallback is misconfigured or returns 401 — refine used to succeed on the primary's second request and now fails.
Two knock-on effects that make this more than a policy preference:
- Every routine blip becomes an ERROR log.
internal/llmobs/observer.go:64-68deliberately logsbudget_starvedatslog.LevelErrorbecause it is "a configuration fault, not an upstream one." Under these defaults that fault is permanent, so the level carries no information. - It destroys the query this PR proposes. The description says querying
llm_model_switch_total{reason="budget_starved"}is how you'd decide whether #220 §1 is real. Onapi_refinethat series will now read ~100% of switches by construction of the defaults, not because of any incident.
refine_budget.go:21 states the precondition itself — REFINE_TIMEOUT >= 2 * LLM_TIMEOUT + backoff — and then the file deliberately ships a default that violates it (90 < 360). Arming a guard under a permanently-violated precondition is a permanent misfire, not a diagnostic. I agree with the reasoning for not raising the default silently; the issue is arming the guard anyway.
Also note the guard cannot rescue the case #220 §3 actually describes. If the primary simply hangs and eats the whole 90s, c.client.Do returns with ctx.Err() != nil and the attempt classifies Terminal (internal/service/llm.go:309-315), so Run returns immediately and no fallback is attempted at all. The guard only helps when the primary fails fast.
Suggested fixes (any one): gate the arming on parentBudget >= 2*perModel; or derive PerModelTimeout from the remaining parent budget rather than the raw LLM_TIMEOUT; or raise the default and accept the latency change explicitly. At minimum, add the budget-matrix test that #220's acceptance criteria already ask for (see P2-6) so the chosen behaviour is pinned.
P2-1 — The histogram measures Run wall-clock, but LLM_TIMEOUT is a per-attempt budget
ObserveResult receives e.Duration = time.Since(start) for the entire Run (internal/llmfallback/fallback.go:174) — including backoff sleeps (1s + 2s) and every model tried. But LLM_TIMEOUT is applied per attempt: http.Client{Timeout: ...} at internal/service/llm.go:87, and context.WithTimeout(ctx, c.timeout) at internal/agent/llm.go:137.
Sizing a per-attempt cap from a whole-run distribution over-estimates exactly where it matters — the P99 is the retried runs, which is where run duration and attempt duration diverge most. On the happy path they coincide, so P95 is roughly usable; P99 is not.
The right input already exists and is being thrown away: AttemptEvent.Duration is delivered to llmobs.Observer.ObserveAttempt (internal/llmobs/observer.go:33) but Metrics.ObserveAttempt (internal/llmobs/metrics.go:301-308) only increments a counter and drops the duration.
Suggestion: add llm_attempt_duration_seconds{path} over the same buckets — it's a two-line change given histogramVec now exists — or narrow the HELP text and the PR rationale to "run latency, for sizing parent budgets (REFINE_TIMEOUT / AGENT_STEP_TIMEOUT)", which is what it genuinely measures.
P2-2 — document_preview is a live untagged path, and it was skipped
The PR pre-emptively tags three CallReduceByPerson* methods it correctly identifies as having no production caller. Meanwhile internal/api/handler/document_preview.go:316 calls client.CallStream(genCtx, …) with no llmfallback.WithPath, on a wired route — internal/api/router/router.go:177, POST /v1/summaries/document/preview.
That endpoint's latency lands in path="unknown", and the new histogram now spends 15 bucket series on that mixed bucket. Given the PR's stated goal is per-scenario percentiles, tagging the path with real traffic seems higher value than tagging three with none. One line, same file pattern as the others.
P2-3 — Metric naming: llm_call_duration_seconds next to the existing llm_call_duration_seconds_total
I dumped the rendered exposition by hand and confirmed there is no collision in Prometheus text format 0.0.4 — _bucket / _sum / _count are all distinct from _total, and both families scrape cleanly. So this is not a blocker.
The concern is downstream: in OpenMetrics a counter's family name is the name minus _total, so both families normalize to llm_call_duration_seconds with conflicting TYPEs. Consumers that normalize — the OTel Collector prometheus receiver, promtool check metrics, OpenMetrics-negotiating scrapers — would see a duplicate family. Since #231 plans to adopt OpenTelemetry for exactly this repo, it's cheap to sidestep now (llm_run_duration_seconds?). Worth noting too that _sum is now the same quantity as llm_call_duration_seconds_total, so the counter is fully redundant and could be deprecated rather than "retained".
Caveat: no promtool or Prometheus binary available in my environment, so this is a naming-convention argument, not an observed scrape failure. Treat it as advisory.
P2-4 — refineTimeout() parsing: the "a typo degrades to the previous behaviour" comment overclaims
internal/api/handler/refine_budget.go:34-50. Only unset / unparsable / non-positive fall back to 90s. Two live failure modes survive:
- Wrong unit.
REFINE_TIMEOUT=90000(someone assumes milliseconds) parses fine → a 25-hour refine deadline. The handler holds the connection and goroutine essentially forever instead of erroring at 90s. - Overflow.
time.Duration(secs) * time.Secondis unchecked.REFINE_TIMEOUT=9223372036854775807yields-1s; all four refine handlers then build an already-expired context and every refine request fails instantly, silently.
Suggestion: clamp to a sane range (e.g. 1s–30m) and log once when the env value is rejected or clamped, so a typo is visible rather than silent. That would make the comment's promise actually true.
P2-5 — REFINE_TIMEOUT is undocumented and CONFIGURATION.md is now stale
CONFIGURATION.md documents all 52 environment variables, including LLM_TIMEOUT, AGENT_STEP_TIMEOUT and TOOL_CALL_TIMEOUT. REFINE_TIMEOUT has no entry — no unit, no default, no stated relationship to LLM_TIMEOUT. That defeats the stated purpose ("a deployment can widen it without a build"): an operator reading the configuration reference cannot discover the knob exists.
Two existing sentences in CONFIGURATION.md:21 also go stale with this PR:
- "API refine has a 90-second request deadline" — no longer fixed.
- "For agent chat … it escalates early when the remaining deadline cannot fit both the pending retry and a fallback attempt" — after this PR that is also true of
api_refine, and per P1-2 it is true unconditionally there.
P2-6 — The two behaviour-changing hunks have zero tests
grep -rn 'refineTimeout|REFINE_TIMEOUT' --include=*_test.go . → (nothing)
grep -rn 'budget_starved|ReasonBudgetStarved' --include=*_test.go internal/service internal/api → (nothing)
The histogram — which is purely additive and cannot change behaviour — got four careful new tests, and they are genuinely good (exact cumulative values, the 400s over-range case, the label-set pin, concurrency). The two hunks that do change runtime behaviour got none.
A budget-matrix table over (model count, PerModelTimeout, parent deadline, backoff) → observed attempt sequence — which is #220's own acceptance criterion 4, already on the books — would have caught P1-1 on the first run. That's the test I'd most like to see added here.
Nits
internal/llmobs/metrics.go:154—newHistogramVeckeeps the caller'sbucketsslice by reference. A defensive copy makes the strictly-increasing invariant thatsort.SearchFloat64sdepends on unbreakable, for one line.internal/api/handler/refine_budget.go:32—RefineTimeoutEnvVaris exported but referenced nowhere, including tests. Either use it in a test or unexport it; right now it's public surface onhandlerwith no consumer.internal/llmobs/metrics_test.go—TestHistogram_LabelSetMatchesCounterdereferencesfams["llm_call_duration_seconds"].sampleswith no nil check, so a rename turns a clean test failure into a nil-pointer panic.TestHistogram_QuantileInputsAreExactguards this correctly a few lines above.- The
if v < 0 { v = 0 }clamp inobserveis untested. refineTimeout()re-reads and re-parses the environment on every request. The cost is trivial next to a multi-second LLM call and it matches theagentStepTimeoutOverrideprecedent the comment cites, so I don't think it needs changing — noting it only because reading env inside a handler tends to attract review comments.
3. What I verified as correct
Worth saying explicitly, because the histogram is the bulk of the diff and it holds up:
- Boundary search.
sort.SearchFloat64sreturns the leastiwithbuckets[i] >= v, which is exactlyle(≤) semantics. Checked on-boundary (0.5 →le="0.5") and over-range (400s →+Infonly). - Over-range samples reach
_sum,_countand+Infrather than being dropped. - Cumulative rendering,
+Inf == _count, and%gshortest-round-trip boundary formatting — I dumped the full exposition and read it line by line. - Lock discipline. One mutex;
writetakes a consistent snapshot of counts/sums/totals before rendering.-raceclean locally. parseExposition's new suffix resolution checks the exact name first, so the pre-existingllm_call_duration_seconds_totalcounter is not misrouted into the histogram family. That ordering matters and it's right.- The
path-only label decision and the reasoning about bucket-series multiplication — agreed, and the label-set pin test is the right way to keep it that way.
On the open question in "Notes for reviewers": I'd leave the bucket layout alone for now. Tightening 60–180s costs you the sub-second refine resolution you need for REFINE_TIMEOUT, and until P2-1 is resolved you don't yet know which band the real signal lives in.
4. Verdict
CHANGES_REQUESTED.
P1-1 and P1-2 are both blocking, and they're the same root cause seen from two ends: PerModelTimeout was added to two call sites without checking what the parent context actually looks like at either. On the worker there is no deadline, so it does nothing; on refine the deadline is smaller than one attempt, so it does something drastic on every blip.
Smallest path to approval, if you want to keep this PR narrow:
- Drop the worker half, or add the aggregate deadline that makes it real (P1-1).
- Decide the refine behaviour deliberately and pin it with a budget-matrix test (P1-2 + P2-6).
- Add the
REFINE_TIMEOUTrow toCONFIGURATION.mdand fix the two stale sentences (P2-5). - Clamp the parsed value (P2-4).
P2-1, P2-2 and P2-3 are fine as follow-ups.
The histogram itself I'd merge today.
5. Coverage note
Ran and verified: full -race test suite on internal/llmobs, internal/llmfallback, internal/api/handler (go1.26.5, all PASS); hand-dumped Prometheus exposition; a synthetic probe against the real llmfallback.Run for both context lineages; repo-wide grep for every context.WithTimeout/WithDeadline outside tests.
Not verified:
- No
promtool/ Prometheus binary available, so P2-3's OpenMetrics normalization concern is reasoned from the spec, not observed. Flagged advisory for that reason. - No deployment manifests reviewed. Whether P1-2 bites today depends on whether
LLM_FALLBACK_MODELSis actually set in each environment — if it's empty,hasNextis false and the refine behaviour is unchanged. Please confirm against the deployment config before deciding P1-2's urgency. - No production metrics. The refine firing rate is derived from the code path and the synthetic probe, not measured against real traffic.
- #220 §2's lease/stuck-scanner overrun (worst case ~18–27 min vs. a ~10-min scanner and 20-min lease) is out of this PR's scope and I did not check whether it's tracked elsewhere. Raising it because P1-1 means it is still fully open.
- CI:
check-sprintandlabelare failing on this PR. Both are project-board automation and unrelated to the diff, but they'll need clearing before merge.
Jerry-Xin
left a comment
There was a problem hiding this comment.
Code Review — PR #232 (octo-smart-summary) — REQUEST_CHANGES
Verified on head 7ed3e73 (checked out locally; go build ./... clean, go vet clean, go test -race -count=1 on ./internal/llmobs/... ./internal/llmfallback/... ./internal/service/... ./internal/api/handler/... all PASS; CI Build/Lint/Test/Test(race,cgo)/Vet/secret-scan/dependency-review/osv-scan green at review time).
🔴 Blocker 1 — PerModelTimeout is inert on worker Map/Reduce; the "guard armed" claim is false there and is now baked into source comments
The guard (internal/llmfallback/fallback.go:306) is gated on the parent context having a deadline (ctx.Deadline(), ok). Every worker LLM entry point propagates context.Background() unchanged — internal/worker/meta_processor.go:78, internal/worker/processor.go:183,187,253, internal/worker/personal_processor.go:623 — and a repo-wide grep finds no WithTimeout/WithDeadline between those roots and callWithPolicyAndModel. So on worker paths the guard never runs and budget_starved is still unemittable there.
I had flagged this in my superseded review as a wording issue; yujiwei is right that it is blocking:
- The same false claim is now asserted in a source comment at internal/service/llm.go:270-278 ("Omitting it silently disabled that guard on every worker Map/Reduce and API refine call"), which the next debugger will read as ground truth.
- It inverts the diagnostic this PR proposes:
llm_model_switch_total{path="worker_map",reason="budget_starved"} == 0will read as "starvation is not happening" when it actually means "the guard never ran" — strictly worse than before, when the absent field was obvious at the call site.
Fix — pick one: (a) add the aggregate worker deadline #220 §2 asks for so PerModelTimeout becomes meaningful (likely its own PR), or (b) keep the one-line change but scope the claim to api_refine and delete the worker sentence from the PR body and the comment at internal/service/llm.go:270-278.
🔴 Blocker 2 — On api_refine the shipped defaults make the guard fire on EVERY first transient failure: a precondition the PR itself documents is violated by default
Byte-verified arithmetic: REFINE_TIMEOUT defaults to 90s (internal/api/handler/refine_budget.go:29) and PerModelTimeout = c.timeout = LLM_TIMEOUT = 180s (internal/config/config.go:210, internal/service/llm.go:85). The guard condition remaining < delay + 2*PerModelTimeout becomes ≤90 < 1 + 360 — always true. Consequences, all verified in code:
- Primary loses its entire retry budget on one blip. Any transient 429/5xx/transport error abandons the primary after ONE attempt (
budget_starved) instead of retrying 3 times. Reachable regression: primary returns one transient 503 then recovers, fallback is misconfigured and answers 401 →ClassifyStatus(401) = Terminal→ refine fails outright, where before this PR the second primary attempt would have succeeded. Scope caveat confirmed:LLM_FALLBACK_MODELSdefaults to empty (internal/config/config.go:209), so single-model deployments are untouched (hasNextfalse) — the regression hits exactly the deployments that configured a fallback, i.e. this PR's audience. - Permanent ERROR-log noise.
budget_starvedis logged atslog.LevelError(internal/llmobs/observer.go:63-69, comment: "costs the primary its retry budget on every single blip"). Under these defaults that is every routine blip on api_refine; the level carries no information. - It destroys the query this PR proposes. On api_refine,
llm_model_switch_total{reason="budget_starved"}reads ~100% of switches by construction of the defaults, not because of any incident. - The guard cannot rescue the hang case it is justified by. A hanging primary eats the 90s inside
c.client.Do; the attempt then seesctx.Err() != niland classifiesTerminal(internal/service/llm.go:310-315), so Run returns with no fallback at all. The guard only changes fast-fail behaviour.
internal/api/handler/refine_budget.go:19-21 states the precondition itself (REFINE_TIMEOUT >= 2 * LLM_TIMEOUT + backoff) and then deliberately ships a default that violates it while arming the guard anyway — that is a permanent misfire, not a diagnostic. Fix options (any): gate the arming on parentBudget >= 2*perModel; derive PerModelTimeout for these call sites from the remaining parent budget; or raise the default and own the latency change explicitly. Whichever is chosen, pin it with the budget-matrix test #220's acceptance criteria already ask for (see below).
Verified good (merge-quality, no changes needed)
- Histogram: bucket units consistent (seconds vs
Duration.Seconds());sort.SearchFloat64sgives correct le-inclusive boundary semantics (on-boundary sample lands in that bucket — pinned by the exact-cumulative test); over-range 400s sample reaches+Inf/_sum/_count; negatives clamped without corrupting_sum; snapshot-under-lock rendering is race-free;Install()is once-per-binary and the hand-rolled registry cannot panic on re-registration. The three new tests (exact cumulative values, label-set pin, concurrency) pass locally with-race. - Observation coverage: every LLM call in the repo travels through
llmfallback.Run(all four call sites; everyclient.Dois inside a Run attempt) and Run emits exactly one terminalObserveResult— one observation per call, no double-counting on retry/fallback/streaming paths. - Path tagging: the three newly tagged
ReduceByPersonvariants indeed have zero production callers (grep-verified; onlyCallReduceByPersonStreamWithModelis wired at internal/worker/meta_processor.go:235, already tagged). Pre-emptive as claimed. - Cross-PR collisions: none with #213 or #215 — neither touches internal/llmobs or internal/service/llm.go, and none of the new symbols (
histogramVec,durationBuckets,withLE,formatBucket,refineTimeout,RefineTimeoutEnvVar,defaultRefineTimeout) appear in either diff.
Non-blocking (agree with yujiwei's list; adding my verified items)
- 🟡 internal/api/handler/document_preview.go:316 calls
CallStreamwithoutWithPathon a live wired route (POST /v1/summaries/document/preview) — its latency lands inpath="unknown"and spends 15 bucket series there. Tagging a path with real traffic is higher value than tagging three with none. One line. - 🟡 CONFIGURATION.md:21 is stale twice over (fixed-90s refine sentence; the escalation sentence now also applies to api_refine), and
REFINE_TIMEOUThas no entry despite the knob's stated purpose. Also: the requiredcode-reviewcheck and merge are blocked until these reviews are resolved. - 🔵
refineTimeout()parse:REFINE_TIMEOUT=9223372036854775807overflowstime.Durationnegative → all four refine handlers build already-expired contexts and every refine fails instantly; a wrong-unit value (90000 read as seconds) parses fine into a 25-hour deadline. Clamp to a sane range and log when rejected. (Same unchecked pattern pre-exists inAGENT_STEP_TIMEOUT; the overflow class matches the finding above.) - 🔵 Zero tests on the two behaviour-changing hunks: nothing pins that
callWithPolicyAndModel/callStreamWithModelpassPerModelTimeout, and no parse table forrefineTimeout(unset/valid/malformed/non-positive). A(models, PerModelTimeout, parent deadline, backoff) → attempt sequencematrix would have caught both blockers. - 🔵 Advisory (yujiwei P2-1/P2-3, concur): the histogram measures whole-Run wall-clock while
LLM_TIMEOUTis per-attempt — fine for sizing parent budgets, not for per-attempt P99;AttemptEvent.Durationalready exists if an attempt-level series is wanted. Namingllm_call_duration_secondsnext tollm_call_duration_seconds_totalis valid in text format 0.0.4 but both normalize to one family under OpenMetrics — cheap to sidestep before the #231 OTel adoption.
Merge state
mergeable_state=blocked is correct and now doubly so: the main ruleset requires 2 approvals + code-owner + last-push approval + thread resolution, and the required code-review status check is red (this review). check-sprint/label failures are project-board automation, not in the ruleset's required list.
Superseded by REQUEST_CHANGES review 5039232364 (verified peer blockers)
mochashanyao
left a comment
There was a problem hiding this comment.
[Octo-Q · automated review]
Verdict: Approve — no blocking findings; notes below (data-flow traced).
Reviewer: Octo-Q (automated review)
PR: #232 | head: 7ed3e737ed1841b958ff8844c3d4284958592401 | base(merge-base): eb9e0e3adabd03208b7d3695290d7bb5c034fae4 | 轮次: 首轮
Code Review — PR #232 (octo-smart-summary)
Summary
This PR adds a labelled latency histogram (llm_call_duration_seconds) to the hand-rolled Prometheus exposition in internal/llmobs, arms the existing deadline-aware fallback escalation on the two generic llmfallback.Run sites by passing PerModelTimeout: c.timeout (internal/service/llm.go:280, :408), extracts the refine LLM budget from four welded 90*time.Second call sites into a REFINE_TIMEOUT env knob with the same 90s default (internal/api/handler/refine_budget.go), and completes PathWorkerReduce tagging across the CallReduceByPerson family. Defaults are deliberately unchanged, so out-of-the-box behavior should be identical except that refine now escalates to a configured fallback earlier on transient failures instead of spending the primary's whole retry budget.
Overall the change is careful: the histogram math, locking, and exposition format are correct, and the timeout wiring is symmetric across call sites. The two findings below are an operator-docs gap and a parse-boundary hardening item, neither blocking.
Verification
Static analysis only at head 7ed3e737ed1841b958ff8844c3d4284958592401; build and tests not executed in this environment.
- ✅ Histogram boundary math —
sort.SearchFloat64sis lower-bound, so a sample exactly on a boundary lands in that bucket (le-inclusive, as the exposition format requires); hand-checked against the exact-value test: 0.25/0.5 →le="0.5"(cum 2), 75 →le="90"(cum 3), 400 → only+Inf/_sum/_count(sum 475.75). - ✅ Concurrency — one mutex covers observe and the snapshot copy in
write;durationBucketsis an immutable package-level slice read outside the lock; the new race test pins loss-free counts. - ✅ Guard arming is zero-safe —
internal/llmfallback/fallback.go:306gates oncfg.PerModelTimeout > 0and onctx.Deadline(), so a zero timeout or deadline-less ctx keeps prior behavior;c.timeouttraces toLLM_TIMEOUT(default 180,internal/config/config.go:210) and equals the per-attempthttp.Client.Timeout. - ✅ Call-site parity — all four refine sites now use
refineTimeout()(internal/api/handler/edit.go:277,:444,internal/api/handler/personal_refine.go:110,:336); the other two productionRunsites (agent chat,CallWithTools) already passedPerModelTimeout; plainCallMap/CallReducewrappers delegate to the taggedWithModelvariants. - ✅ Metric wiring end-to-end —
llmobs.Installin bothcmd/summary-apiandcmd/summary-worker, everyRunexit path emitsResultEvent.Duration, andWritePrometheusis served atinternal/api/router/router.go:198.
Findings
No P0/P1 issues; two P2 items below.
P2 — REFINE_TIMEOUT is undocumented and CONFIGURATION.md still hardcodes the 90s refine deadline (internal/api/handler/refine_budget.go:33)
The whole point of the new file is that the refine budget becomes one operator-tunable knob, but CONFIGURATION.md never mentions it: there is no REFINE_TIMEOUT row in the env table, and the LLM_FALLBACK_MODELS row at CONFIGURATION.md:21 still states "API refine has a 90-second request deadline" as a constant. Since this PR also arms the deadline guard on refine calls, the guidance the docs already give for agent chat (maxAttempts*LLM_TIMEOUT + backoffs <= AGENT_STEP_TIMEOUT) now has a refine analogue (REFINE_TIMEOUT >= 2*LLM_TIMEOUT + backoff, per the comment at internal/api/handler/refine_budget.go:21) that operators also need. Add the env row with its degrade-to-90s semantics and update the stale sentence.
P2 — refineTimeout() Duration overflow defeats its own typo contract (internal/api/handler/refine_budget.go:50)
time.Duration(secs) * time.Second overflows for values strconv.Atoi still accepts: any REFINE_TIMEOUT above 9,223,372,036 (about 292 years) wraps to a negative Duration, context.WithTimeout then yields an already-expired context, and every refine request fails immediately with deadline exceeded. That contradicts the function's stated contract (":36") that an unparsable value degrades to the historical 90s instead of removing the deadline. The identical unbounded pattern pre-exists in agentStepTimeoutOverride (internal/agent/profile.go:171), so this is not newly introduced logic — but this new knob can carry the fix: reject secs > math.MaxInt64/int64(time.Second) as unparsable, and add parse-branch tests (empty/garbage/negative/overflow), which the new file currently lacks.
Things I checked that are fine
- Exposition shape: HELP/TYPE under the base name, cumulative
_bucketlines withleappended viawithLE,_sum/_countwithoutle,formatBucketround-trips every boundary ("0.5"…"300"),+Infequals the total, negative samples clamp to 0 instead of corrupting_sum. - Cardinality: histogram labels are
pathonly (pinned byTestHistogram_LabelSetMatchesCounter), path is a closed 7-value constant set, series count = paths × 15 lines. - Test-side
parseExpositionsuffix resolution only fires for the new histogram family; the pre-existingllm_call_duration_seconds_totalcounter family is untouched. - Worker Map/Reduce behavior is unchanged today: worker contexts carry no deadline, so the newly armed guard is inert there until a deadline exists — harmless future-proofing, and
timeimports remain used in both edited handlers. - The three newly path-tagged
CallReduceByPerson*functions have no production callers yet (tests only), so the tagging cannot shift any live metric attribution.
Verdict: APPROVED
No P0/P1 blockers found. The histogram math, locking, and exposition format hold up under static tracing of every consumed value, and the timeout wiring is symmetric across call sites. The two P2 items — documenting REFINE_TIMEOUT and hardening its parse boundary — are non-blocking and can land in a follow-up.
Octo 附录(内部审查记录,非对外正文)
验证结论
✅ 直方图数学/并发/渲染正确(internal/llmobs/metrics.go:186-258,手工对 sort.SearchFloat64s 语义与测试精确值交叉验证);✅ PerModelTimeout 接线对称且 0 值/无 deadline 安全(internal/llmfallback/fallback.go:306);✅ 四处 refine 调用点全部换用 refineTimeout()(internal/api/handler/edit.go:277,444、internal/api/handler/personal_refine.go:110,336);
数据流回溯(被消费数据 → 上游来源 → 是否真流到消费点)
e.Duration.Seconds()→llmfallback.Run全部 5 个ObserveResult出口均设Duration: time.Since(start)(fallback.goempty-model/loop-top-ctx-err/Success/Terminal/exhausted)→ 每次完成的 Run 都进直方图 ✅e.Path→cfg.pathFor(ctx):Config.Path(agent Chat)或WithPath标签;refine handler 在context.WithTimeout内层先打PathAPIRefine(顺序已验),worker 包装函数入口打PathWorkerMap/Reduce;未打标 →PathUnknown常量,永不为空 ✅c.timeout→NewLLMClient(timeoutSec)←cfg.LLMTimeout←envInt("LLM_TIMEOUT", 180)(internal/config/config.go:210);与http.Client.Timeout同值(单次 attempt 预算语义一致);为 0 时守卫自动不启用(>0门控)✅refineTimeout()→REFINE_TIMEOUTenv,TrimSpace+Atoi,空/非法/非正 →defaultRefineTimeout=90s;被 4 个context.WithTimeout消费 ✅(>9.22e9 秒溢出为负 → 见 P2-2)h.buckets=durationBuckets→ 包级不可变切片,SearchFloat64s只读消费,锁外读安全 ✅- 测试 hand-feed → 直接调
ObserveResult(即生产 observer 接缝本身:Install→SetDefaultObserver→Run调用它);端到端链cmd/*/main.go Install+internal/api/router/router.go:198 WritePrometheus静态验证 ✅ 无绕过真实路径问题
盲点 checklist
- C1 双路径 parity:HIT 已清 — 4/4 refine 点替换(grep 证明仓内唯一剩余
90*time.Second是默认常量本身);2/2 通用 Run 点补 PerModelTimeout(另 2 个生产 Run 点 agent Chat/CallWithTools 已有);ByPerson 家族 WithPath 补齐(此前仅 StreamWithModel 有标签,其余 3 个无生产调用者,补标签无运行时归因漂移);plain wrapper 全部委托带标签的 WithModel 变体。 - C2 control-flow ordering/嵌套复用:CLEAR —
refineTimeout()无状态、每调用点现读,嵌套/复用无双重作用;守卫检查在 backoff sleep 之前、每 attempt 至多一次、不改变任何状态。安全控件非 canonical 形式试穿:env 值 "+90"(Atoi 接受,正常)、" 90 "(TrimSpace 覆盖)、"90.5"/"1e3"(Atoi 拒绝→默认)、超大值(溢出,P2-2)。 - C3 授权边界:N/A — 无 auth/jail/tool/凭证面改动。
- C4 授权生命周期/容器级联:N/A — 无鉴权改动。
- C5 build/运行期路径:静态推演(审查约束不跑 build/test,报告已如实标注)——
timeimport 在两个改动 handler 中仍有其他引用(edit.go:124、personal_refine.go:249等),新增strconvimport 被formatBucket使用;Install→observer→histogram→/metrics 全链静态走通。 - C6 治理/文档自洽:HIT — CONFIGURATION.md 与新旋钮漂移(P2-1);不涉及 SECURITY.md/披露流程。
- R3 分布式副作用:CLEAR — 仅进程内指标,无通知/推送/计数 fan-out;多实例各自 expose,scraper 端
sum by(path,le)聚合,无 dedup 问题。
定级说明(R1/R2/R4)
- P2-1(文档漂移):R2=new(本 PR 引入可调旋钮并使守卫在 refine 生效,文档契约随之过期);不满足 R1(无运行期破坏)→ P2。
- P2-2(Duration 溢出):R2=new code 复刻既有模式(
agent/profile.go:171同款无上界);触发需 >292 年的 env 配置,属配置错误非运行期可达,失败模式为显性全量报错而非静默错误数据 → 按 R1 判不构成"生产可达的能工作路径破坏" → P2 而非 P1。 - R4:无 P0/P1 → APPROVED。
跨轮 blocker 复检(R6)
N/A — 本 PR 首轮审查,无上一轮未解决 blocker。
流程备注
本轮按 skill 单腿执行:当前 skill 安装不含双模型 fan-out 脚本(glm_review.py/merge_reviews.py 缺失),无 /tmp/merged.findings.json,按降级规则从 /tmp/review.final.json 渲染。gh 在本环境无凭据,base 判定完全用本地 git(merge-base eb9e0e3 = origin/main tip,单 commit PR)。
…run vs attempt latency Addresses both P1 blockers from @yujiawei and @Jerry-Xin on Mininglamp-OSS#232. ## P1-1 + P1-2: revert PerModelTimeout on Call/CallStream Both reviewers are right, and the two findings are one root cause: the field was added without checking the parent context at either consumer. llmfallback.Run's escalation is gated on ctx.Deadline() being present: - worker Map/Reduce roots at context.Background() with no deadline anywhere down the chain, so the field was inert. budget_starved remains unemittable there. Worse, the PR asserted the opposite in a source comment, which would have inverted the diagnostic: reading {path="worker_map",reason="budget_starved"} == 0 as "not happening" when it means "never ran". - api_refine passes 90s while PerModelTimeout would be LLM_TIMEOUT (180s), so `remaining < delay + 2*PerModelTimeout` is 90 < 361 — permanently true. Any transient 429/5xx would abandon the primary after ONE attempt, log budget_starved at ERROR on every blip, and make that series read ~100% of switches by construction of the defaults. The very query this PR proposed for diagnosing Mininglamp-OSS#220. Both entry points are shared by worker and refine, so the field cannot be scoped to one side here. Reverted, with a comment recording why arming it needs either Mininglamp-OSS#220 §2's aggregate worker deadline or a per-attempt budget derived from the remaining parent budget. Also corrects the attribution: the worker gap is Mininglamp-OSS#220 §2 (aggregate deadline vs the ~10min stuck scanner and 20min lease), not §1, which is the agent path and already passed PerModelTimeout. ## P2-4: clamp and log REFINE_TIMEOUT The old comment claimed a typo degrades to previous behaviour; it did not. REFINE_TIMEOUT=90000 (milliseconds assumption) parsed into a 25-hour deadline, and int64-max overflowed time.Duration to a negative value, making all four refine handlers build an already-expired context — every refine failing instantly and silently. Now clamped to [1s, 30m] with a once-per-process log on any rejection or clamp. ## P2-1: add llm_attempt_duration_seconds LLM_TIMEOUT is a per-attempt cap, but ResultEvent.Duration is whole-run wall-clock including backoffs and earlier models. Sizing the cap from the run distribution over-estimates precisely at P99, because the P99 IS the retried runs. AttemptEvent.Duration was already delivered to ObserveAttempt and discarded; it now feeds a per-attempt histogram labelled {path, outcome} (no model/position — bucket series multiply by len(buckets)+3). ## P2-3: rename llm_call_duration_seconds -> llm_run_duration_seconds Valid in text format 0.0.4, but under OpenMetrics a counter's family name is its name minus _total, so it would collide with the existing llm_call_duration_seconds_total. Free to fix now, expensive once dashboards exist. The new name is also more honest about what it measures. ## P2-2: tag document_preview POST /v1/summaries/document/preview is a live wired route calling CallStream with no WithPath, so its latency landed in path="unknown". Adds PathDocumentPreview. Tagging a path with real traffic matters more than the three pre-emptive tags already in this PR. ## P2-5: document REFINE_TIMEOUT, fix two stale sentences CONFIGURATION.md gains a REFINE_TIMEOUT row. The LLM_FALLBACK_MODELS row no longer claims refine has a fixed 90s deadline, and now states which paths the escalation guard is actually active on and why. ## P2-6 + nits - refine_budget_test.go: 15-row parse table covering unset/valid/ malformed/non-positive/wrong-unit/overflow, asserting the result is always a usable positive deadline inside the clamp range - negative-observation clamp test (a single negative sample would skew _sum permanently) - a test pinning that run and attempt histograms report different values for the same logical call - defensive copy of the bucket slice (SearchFloat64s needs a stable strictly-increasing slice) - label-set pin now nil-guarded and covers both histograms - RefineTimeoutEnvVar unexported (no consumer) Not in this PR: the aggregate worker deadline (Mininglamp-OSS#220 §2) and its budget-matrix test. That test would have caught P1-1 on the first run. Verification: CGO_LDFLAGS=-L/home/mlamp/.local/lib go test -race -count=1 ./... PASS CGO_LDFLAGS=-L/home/mlamp/.local/lib go vet ./... PASS git diff --check PASS Refs Mininglamp-OSS#231, Mininglamp-OSS#220
|
Thanks to both reviewers — the two P1s were correct, and they were one root cause seen from two ends. Pushed P1-1 / P1-2 —
|
yujiawei
left a comment
There was a problem hiding this comment.
Code Review — PR #232 (octo-smart-summary)
Re-review at head 33a40bb, against merge-base eb9e0e3. I checked the branch out and ran locally (go1.26.5): go build ./..., go vet ./internal/llmobs/... ./internal/api/handler/... ./internal/service/..., and go test -race -count=1 ./internal/llmobs/... ./internal/llmfallback/... ./internal/api/handler/... ./internal/service/... — all clean, all PASS. CI on this head is green except check-sprint (project-board automation, unrelated to the diff).
The previous round's two blockers are genuinely fixed, not papered over. Reverting the PerModelTimeout hunk and replacing it with a comment that explains why the field is absent is the right call, and the new llm_attempt_duration_seconds series is a better answer to the run-vs-attempt problem than the doc-narrowing I suggested. Every P2 and nit from the last round is addressed too.
One thing did not survive the fix, and it is the same class of defect the last round blocked on: the CONFIGURATION.md sentence that was rewritten to state the guard's actual scope now states it wrongly, and it does so in the direction that was previously correct. That is the only blocker, and it is a one-line edit.
1. Spec compliance
Result: not met — one deviation, plus a stale PR title.
Measured against this PR's own "Change" section:
| Stated change | Status |
|---|---|
llm_run_duration_seconds{path} — whole-Run wall-clock |
Implemented as described |
llm_attempt_duration_seconds{path,outcome} — single attempt |
Implemented; AttemptEvent.Duration correctly excludes the backoff sleep (fallback.go:322 starts the clock after the select) |
| Buckets fixed at package scope, 0.5s → 300s | Implemented; defensive copy in newHistogramVec as requested |
| Rename to avoid the OpenMetrics family collision | Implemented |
REFINE_TIMEOUT, default unchanged at 90s, clamped to [1s, 30m], logged once |
Implemented; all four call sites converted (no 90 * time.Second left outside the const and its test) |
PathDocumentPreview on the live preview route |
Implemented; Call/CallStream set no path of their own, so the caller's tag propagates — verified |
Three CallReduceByPerson* variants tagged |
Implemented |
CONFIGURATION.md: add the REFINE_TIMEOUT row, correct two sentences in the LLM_FALLBACK_MODELS row |
Diverges — see 2.1 |
Tests (exact cumulative, 400s over-range, label pins nil-guarded, negative clamp, run-vs-attempt divergence, concurrency, 15-row parse table, parseExposition suffix resolution) |
All present; the parse table is exactly 15 rows |
Stale title. The PR is still titled "feat(obs): histogram for LLM call latency + arm the fallback deadline guard", but this head explicitly does the opposite of the second clause — internal/service/llm.go:270-286 now documents at length why the guard is deliberately not armed. If this is squash-merged, git log will permanently assert the reverted behaviour, which is the same trap the last round blocked on, one level up. Not a code change; please just fix the title box before merging.
2. Code quality
Result: changes requested. One P1, five P2, four nits.
P1 — CONFIGURATION.md:21 now says the early-escalation guard is active on tool calls. It is not, on any production caller.
The rewritten sentence is:
The early-escalation guard … requires BOTH a per-attempt budget and a parent deadline, so today it is active on agent chat and tool calls only — worker Map/Reduce roots at a deadline-less context, and API refine deliberately does not arm it …
The rule it states is correct. The conclusion it draws from that rule is not, and the sentence contradicts itself. Walking the two candidate readings of "tool calls":
PathToolCall (CallWithTools). It does set the per-attempt budget — internal/service/llm.go:569, PerModelTimeout: c.toolCallTimeout. But the guard is gated on the parent context carrying a deadline (internal/llmfallback/fallback.go:306-315; PerModelTimeout is budget arithmetic only, it never wraps the attempt context). Every production caller of CallWithTools is the worker:
internal/worker/processor.go:755— thetoolCallFnclosure defined at:753, over thectx := context.Background()created atinternal/worker/processor.go:739internal/worker/personal_processor.go:706, reached e.g. frompersonal_processor.go:801(pipeline.ResolveTopicTarget(ctx, …)) with that same untimed context
Nothing between those roots and the tool call adds a deadline. The only context.WithTimeout in internal/pipeline on this side is octo_search_fetch.go:131, and it is scoped to fetchViaBatch (message fetching via the search client), which invokes no toolCallFn. So ctx.Deadline() returns ok == false and the guard cannot fire — the same argument the row itself already makes for worker Map/Reduce.
PathAgentTool (merge / narrow / summarize). These go through Call / CallStrict / CallDisclosingTruncation → callWithPolicyAndModel, which as of this head sets no PerModelTimeout at all (internal/service/llm.go:270-286). Guard not armed regardless of deadline.
So under either reading the claim is false, and the only path where the guard actually runs today is agent_chat: PerModelTimeout at internal/agent/llm.go:101 plus a real parent deadline from internal/agent/runner.go:156 (context.WithTimeout(ctx, r.policy.StepTimeout)).
What makes this blocking rather than a nit is that the diff introduced it. The pre-PR sentence was:
For agent chat, keep
maxAttempts*LLM_TIMEOUT + backoffs (3s) <= AGENT_STEP_TIMEOUT; it escalates early when the remaining deadline cannot fit both the pending retry and a fallback attempt.
Scoped to agent chat — correct. This PR broadened it. An operator reading the configuration reference will now believe the worker's tool-call path has starvation protection it does not have, and anyone picking up #220 §2 will read "tool calls: armed" and skip exactly the path that needs the aggregate deadline. That is the operational trap the last round blocked on, moved from a Go comment into the file operators actually read.
Fix: drop and tool calls — so today it is active on agent chat only — and, if you want the exclusion list to stay complete, add the one-clause reason (tool calls set a per-attempt budget but their only callers are the worker, which has no parent deadline). One line, no code change.
P2-1 — CallRaw is still untagged on two live worker call sites
The PR correctly hunted down document_preview by reasoning that a wired route landing in path="unknown" is worth more than tagging three methods with no callers. The same sweep misses CallRaw:
internal/worker/processor.go:763-765— thellmFnclosure,检索后裁剪 PostRetrievalNarrowinternal/worker/personal_processor.go:716-718— same shape
CallRaw (internal/service/llm.go:547-554) delegates to Call, which sets no path, and both closures carry the untimed worker context with no WithPath anywhere above them. Post-retrieval narrowing runs on every worker task, so this is real traffic, and it now costs path="unknown" a full bucket family on llm_run_duration_seconds plus one per observed outcome on llm_attempt_duration_seconds — mixed in with whatever else falls through. Either tag the two closures or give them their own worker_narrow path.
P2-2 — CONFIGURATION.md:53 calls REFINE_TIMEOUT a "Total request deadline", which the two streaming endpoints cannot enforce
Both streaming refine handlers clear the response write deadline before streaming:
// internal/api/handler/edit.go:429 (and personal_refine.go:321)
_ = http.NewResponseController(w).SetWriteDeadline(time.Time{})If a client stays connected but stops reading, writeSSE / Flush blocks once the socket buffer fills, and cancelling llmCtx does not interrupt an in-flight write. There is also no WriteTimeout on the server (cmd/summary-api/main.go:128, :135) to bound it. So on RefineSummaryStream and RefinePersonalSummaryStream, REFINE_TIMEOUT bounds the LLM run, not the request.
This behaviour predates the PR (the SetWriteDeadline call comes from #157) and I am not asking you to fix it here. It becomes in-scope only because this PR is the one making the promise: the new row says "Total request deadline … for the four summary-refine endpoints … both streaming and non-streaming". Narrowing that to "the LLM budget for the refine call" would keep the row true. Worth its own issue.
P2-3 — llm_attempt_duration_seconds is right-censored at LLM_TIMEOUT, so it cannot answer half the question its HELP text claims
internal/llmobs/metrics.go:316: "This is the series to size the per-attempt LLM_TIMEOUT from."
Every attempt is already capped at LLM_TIMEOUT: http.Client{Timeout: …} at internal/service/llm.go:89, and context.WithTimeout(ctx, c.timeout) at internal/agent/llm.go:137. An upstream that would have taken 400s is recorded at ~180s (and classified retry_same_model, since ctx.Err() is nil when the client timeout fires — internal/service/llm.go:318-322). The distribution's right tail is therefore a pile-up at the current cap, sitting exactly on the le="180" boundary.
That is fine for deciding whether to lower LLM_TIMEOUT, and useless for deciding whether raising it would recover requests — the observations that would tell you were truncated by the cap you are trying to size. Given the whole point of the series is #220's timeout decision, one clause in the HELP saying so would stop someone reading a censored P99 as the real one.
P2-4 — the attempt histogram's cardinality reasoning omits its own second label
internal/llmobs/metrics.go:332-336 justifies excluding model and position because "bucket series multiply by len(buckets)+3" — but the label set it ships is {path, outcome}, and outcome multiplies too. Concretely: 8 paths (observer.go:10-21, including unknown) × 4 reachable outcomes × 15 lines ≈ 480 series for this family alone, against 120 for runDur. That is affordable and I am not asking you to drop outcome — the "a timed-out attempt and a fast 403 have different distributions" argument is right. But the comment reads as if path were the only dimension, and it is the comment a future reader will use to decide whether adding one more label is cheap.
P2-5 — llm_call_duration_seconds_total is now exactly llm_run_duration_seconds_sum
Both are cumulative Run seconds labelled by path, both fed from e.Duration in the same ObserveResult (metrics.go:373 and :377). The PR keeps the counter as "purely additive", which is the safe choice for this PR, but they are now two hand-maintained copies of one quantity that will silently diverge the first time someone edits one observe site. Worth a deprecation note on the counter's HELP so the next person knows which one is canonical.
Nits
internal/api/handler/refine_budget.go:87—if d < minRefineTimeoutis unreachable.secs <= 0is rejected at:76, sosecs >= 1andd >= 1salways. The "below the minimum; clamped" log can never fire, and the test'sat the minimumrow exercises the pass-through, not the clamp. Either drop the branch or move the floor check before the<= 0rejection if you wantREFINE_TIMEOUT=0to clamp rather than fall back.internal/api/handler/refine_budget.go:75—strconv.Atoireturns a platform-widthint. On a 32-bit build the9223372036854775807row of the parse table would hitErrRangeand return the default instead ofmaxRefineTimeout, failing the test. Irrelevant for this deployment target;strconv.ParseInt(raw, 10, 64)would make the table architecture-independent.internal/llmobs/metrics_test.go:746— the doc comment says "path is the only permitted label", but theallowedmap two lines down permitsoutcomeonllm_attempt_duration_seconds. Stale as written.internal/api/handler/refine_budget_test.go— theunsetrow does not defend against an ambientREFINE_TIMEOUTin the test environment.t.Setenv(...)followed byos.Unsetenv(...)in the!tc.setbranch would register the cleanup and pin it.
3. What I verified as correct
- Boundary semantics.
sort.SearchFloat64sreturns the leastiwithbuckets[i] >= v, which isle(≤) inclusive. Checked on-boundary (0.5→le="0.5"), just-under (0.4999→le="0.5"), and over-range (400→+Infonly, still in_sum/_count). - Cumulative rendering,
+Inf == _count,%gshortest-round-trip on both boundaries and_sum. - Lock discipline. The boundary search is outside the lock (buckets are immutable after the defensive copy);
writesnapshots counts, sums and totals under one acquisition.counts[l]is allocated before thei < len(buckets)check, so an over-range-only series still registers a key and renders.-raceclean. parseExposition's suffix resolution checks the exact name first, sollm_call_duration_seconds_totalis not misrouted into a histogram family — and after the rename there is no ambiguity left at all.- Attempt vs run semantics.
AttemptEvent.Durationstarts after the backoffselect, so the 20s-vs-21s assertion inTestAttemptHistogram_IsPerAttemptNotPerRunis measuring the right thing. log.Printfinrefine_budget.gomatches the handler package convention exactly (144log.Printf, 0slog), so no consistency issue there.- Per-request env read. I raised no objection last round and still have none: it matches the
agentStepTimeoutOverrideprecedent it cites, the cost is nothing next to a multi-second LLM call, and the handlers really are constructed in tests without a deps container. - The 30m clamp ceiling is well chosen, not arbitrary: worst-case reachable run (3 attempts × 180s × 2 models + backoffs ≈ 18 min) sits under it, and
c.Request.Context()still cancels on client disconnect. - Everything from the previous round: P1-1 and P1-2 resolved by reverting the hunk and recording why; P2-1 (run vs attempt) answered with a second histogram rather than a doc narrowing; P2-2 (
document_preview), P2-3 (naming), P2-4 (clamp + log), P2-5 (CONFIGURATION.mdrow), P2-6 (parse table) all done; all four nits (bucket copy, unexported env const, nil-guarded label test, negative-clamp test) done.
4. Verdict
CHANGES_REQUESTED.
The single blocker is the CONFIGURATION.md:21 guard-scope sentence (P1) — and tool calls is wrong and the diff introduced it. That plus the PR title are both edits you can make without touching code. Everything else on this list is a P2 or a nit and I would not hold the PR for any of them; the histogram work is merge-quality and the response to the last round was thorough.
Smallest path to approval:
- Drop
and tool callsfromCONFIGURATION.md:21(P1). - Fix the PR title so the squash commit does not assert the reverted behaviour.
- Optional but cheap while you are in there: P2-1 (two
CallRawtags) and therefine_budget.go:87dead branch.
P2-2 through P2-5 are fine as follow-ups.
5. Coverage note
Ran and verified: go build, go vet, and go test -race -count=1 across internal/llmobs, internal/llmfallback, internal/api/handler, internal/service (go1.26.5, all PASS); hand-traced the histogram boundary/cumulative/render path; repo-wide grep for every context.WithTimeout/WithDeadline outside tests, and a full call-graph walk from each worker root to every llmfallback.Run entry point; enumerated every LLM call site in the repo against its WithPath tag; confirmed all four refine call sites converted. Two independent parallel review passes were run alongside mine and both completed; their findings are folded in above, each one re-verified against the source before inclusion (the CallRaw and stale-title items were independently reached by more than one pass; the SSE write-deadline item came from one and I downgraded it to P2 after confirming it predates this PR).
Not verified:
- No
promtoolor Prometheus binary available, so the exposition was read and hand-parsed, not scraped. The OpenMetrics reasoning behind the rename is from the spec, not an observed scrape — but the rename removes the risk either way, so nothing turns on it now. - No deployment manifests reviewed (different repo). Whether
REFINE_TIMEOUTorLLM_FALLBACK_MODELSis set per environment is unconfirmed; P2-2's exposure depends on the former. - No dashboards or alert rules checked for consumers of
llm_call_duration_seconds_totalthat P2-5 would affect. - No production metrics. The censoring in P2-3 is derived from the code path, not measured.
- #220 §2's lease / stuck-scanner overrun (worst case ~18–27 min against a ~10-min scanner and a 20-min lease) is correctly listed as out of scope here and remains fully open. Please make sure it is tracked before this merges, since the reverted hunk was the only thing gesturing at it.
- The
SetWriteDeadlinebehaviour in P2-2 was traced statically; I did not exercise a stalled-reader client against a running server.
Jerry-Xin
left a comment
There was a problem hiding this comment.
Re-review @ 33a40bb0 (fix commit: drop the PerModelTimeout hunk; clamp REFINE_TIMEOUT; split run vs attempt latency)
Byte-verified delta against the previously reviewed head 7ed3e737ed18 (merge-base eb9e0e3): the fix commit is honest — the arming hunks are gone from both Call/CallStream entry points, the histogram is split into run + attempt series, refineTimeout() gets a clamped parse with real tests, and document_preview is tagged. Every prior-round blocker is resolved at the code level. The revert did leave one blocking documentation contradiction behind.
🔴 Blocking
🔴 1. REFINE_TIMEOUT >= 2 * LLM_TIMEOUT + backoff is stale after the revert — following it still leaves refine fallback unreachable in the worst case
internal/api/handler/refine_budget.go:21 and the new CONFIGURATION.md REFINE_TIMEOUT row both state:
For a fallback to get one full attempt the budget must satisfy roughly:
REFINE_TIMEOUT >= 2 * LLM_TIMEOUT + backoff
That formula was only true under the arming behaviour this commit reverted (where the budget guard abandoned the primary after its first retry). After the revert, callWithPolicyAndModel runs with MaxAttempts: 3 and no PerModelTimeout, so the primary exhausts three full attempts before switching:
- A hanging attempt is cut by
http.Client.Timeout(=LLM_TIMEOUT, 180s default) and classifiesRetrySameModelbecause the parent context is still alive (internal/service/llm.go:318-323). - Only when the parent deadline fires inside an attempt does it classify
Terminal(service/llm.go:319-321), andRunreturns without ever trying a fallback.
Worst-case budget for one complete fallback attempt = 3 primary attempts × LLM_TIMEOUT + 1s + 2s backoffs (internal/llmfallback/fallback.go:109, backoff = 2^(a-1) s) + one LLM_TIMEOUT for the fallback = (MaxAttempts+1) * LLM_TIMEOUT + 3s = 723s at defaults, not 363s. At the documented 363s: attempts 1–2 plus backoff consume 361s, the parent dies during the third backoff/attempt → ctx.Err() → Terminal → no fallback attempt ever starts. An operator who sizes REFINE_TIMEOUT with the documented formula gets exactly the failure the row's own previous sentence warns about ("if a hanging primary consumes it, no fallback attempt can start").
This is a docs/comment fix, not a code change — but it is this PR's own new text contradicting this PR's own shipped behaviour, on exactly the quantity (refine fallback reachability) the previous round flagged. Fix: correct the refine_budget.go comment, the CONFIGURATION.md row, and the PR body to the real worst case — e.g. "a fallback gets one complete attempt only when REFINE_TIMEOUT >= (MaxAttempts+1) * LLM_TIMEOUT + backoffs (723s at defaults); below MaxAttempts * LLM_TIMEOUT + backoffs (543s) a hanging primary exhausts the budget before a fallback can start" — or state plainly that under the 3-attempt semantics a hanging primary makes fallback unreachable at any realistic budget, and the knob exists to be sized against measured refine percentiles.
💬 Non-blocking
- 🟡
CONFIGURATION.md(LLM_FALLBACK_MODELSrow) and the PR body say the early-escalation guard "is active on agent chat and tool calls only". The tool-call path also sits on a deadline-less context:CallWithToolsis only invoked from the worker pipelinetoolCallFnclosures (internal/worker/processor.go:755,internal/worker/personal_processor.go:706), whose ctx roots atexecutePipeline'sctx := context.Background()(processor.go:739) with noWithTimeout/WithDeadlineanywhere between (onlyocto_search_fetch.gowraps, on a different path). The guard (fallback.go:306-315) is gated onctx.Deadline(), so it cannot fire on tool calls either — agent chat (runner.go:156step deadline) is the only live path. Docs-only, and the tool-call inertness pre-exists this PR, but the sentence is new and mildly repeats last round's failure mode. - 🔵
internal/llmfallback/observer.go:19comment saysPOST /v1/summaries/document/preview; the mounted public path is/api/v1/summaries/document/preview(internal/api/router/router.go:177, pinned bydocument_preview_route_test.go). Trivial. - 🔵 The
d < minRefineTimeoutbranch inrefine_budget.gois unreachable (Atoirejects non-positive, sosecs >= 1⇒d >= 1s= min). Harmless defensive code; noting only.
Prior-round findings, adjudicated byte-against 33a40bb0
| Finding | Status |
|---|---|
| Jerry-Xin 🔴1 / yujiwei P1-1 — guard inert on worker Map/Reduce, claim it was armed | FIXED — PerModelTimeout removed from both Run config literals (service/llm.go:287, :415); comments replaced by an accurate why-not-to-arm note; PR title/body rewritten ("Deliberately out of scope"); #220 §2 attribution corrected |
| Jerry-Xin 🔴2 / yujiwei P1-2 — refine guard misfires on every first retry | FIXED — field unset ⇒ the cfg.PerModelTimeout > 0 gate (fallback.go:306) is false on api_refine; budget_starved can no longer read ~100% of refine switches by construction of the defaults |
| yujiwei P2-1 — attempt-level series | FIXED — llm_attempt_duration_seconds{path,outcome}, exactly one observation per attempt (fallback.go:324); divergence pinned by test (2×10s attempts + 1s backoff ⇒ attempt _sum 20s vs run _sum 21s); labels deliberately narrow (no model/position) |
yujiwei P2-2 — document_preview untagged |
FIXED — PathDocumentPreview added; the route's single CallStream site tagged (document_preview.go:317-318); this is what the file is doing in the delta — requested fix, not drift |
| yujiwei P2-3 — OpenMetrics name collision | FIXED — renamed llm_run_duration_seconds with the rationale recorded; repo-wide grep finds no consumer of the old histogram name (it never shipped) |
| yujiwei P2-4 / mochashanyao 🟡 — clamp + overflow | FIXED — [1s, 30m] clamp with a pre-multiplication overflow guard (secs > maxRefineTimeout/time.Second checked before the multiply, so no time.Duration wrap) and once-per-process logging; wrong-unit (90000→30m) and int64-max (→30m) rows in the parse table |
yujiwei P2-5 / mochashanyao 🟡 — REFINE_TIMEOUT docs |
PARTIAL — row added, stale 90s sentences fixed, but the row carries the stale formula above (🔴) and the inaccurate guard-scope sentence (🟡) |
| yujiwei P2-6 — tests for the behaviour-changing hunks | FIXED — 15-row parse table + default-pin test + negative-clamp test + run-vs-attempt test; the budget-matrix test moving to the #220 §2 worker-deadline PR is the right home now that nothing arms the guard in this PR |
| yujiwei nits (defensive bucket copy, unexport env var, nil-guarded label pin, negative clamp untested) | FIXED — all four; RefineTimeoutEnvVar has zero remaining references |
| Histogram core (prior head) | Still merge-quality: build/vet clean, -race green, buckets defensively copied in newHistogramVec, negative observations clamped in observe |
Verification performed at this head
git diff 7ed3e737ed18..33a40bb0dec3reviewed hunk-by-hunk (8 files, 637 lines).go build ./...✅ ·go vet ./...✅go test -race -count=1 ./internal/llmobs/... ./internal/llmfallback/... ./internal/api/handler/... ./internal/service/...✅ all ok; new tests re-run verbosely and passing (TestRefineTimeout_ParseTable15 subtests,TestRefineTimeout_DefaultIsUnchanged,TestAttemptHistogram_IsPerAttemptNotPerRun,TestHistogram_NegativeObservationIsClamped, label-set pin, quantile-inputs exact).- Guard context lineage enumerated for all four
Runsites: agent chat (step deadline ⇒ guard live; pre-existing), tool call (deadline-less ⇒ inert; pre-existing), workerCall/CallStream(deadline-less; field now unset), refine (90s parent; field now unset). - Cross-PR: #213 and #215 are both already merged and are ancestors of this PR's merge-base — no open-PR symbol collision possible; only shared file is CONFIGURATION.md.
- CI: Build / Lint / Test / Test (race, cgo) / Vet / dependency-review / history / label / pr-title-lint / osv-scan / secret-scan all pass;
check-sprintis project-board automation and not in the required ruleset;code-reviewstatus check is this review.
Verdict
REQUEST_CHANGES — one 🔴: the revert left the refine fallback-budget formula stale in refine_budget.go + CONFIGURATION.md (+ PR body); the documented 363s budget provably cannot reach a fallback attempt in the hanging-primary worst case the docs themselves discuss (723s at defaults). Everything else raised in both prior reviews is fixed and byte-verified. The remaining fix is docs/comment-only; with it, this is approvable.
mochashanyao
left a comment
There was a problem hiding this comment.
[Octo-Q · automated review]
Verdict: Approve — no blocking findings; notes below (data-flow traced).
Code Review — PR #232 (octo-smart-summary)
Reviewer: Octo-Q (automated review)
Summary
This PR adds latency histograms for the LLM fallback runner, makes the API refine deadline configurable, and closes two remaining path-label gaps. It introduces two hand-rolled cumulative histograms in internal/llmobs — llm_run_duration_seconds (whole-Run wall-clock, by path) and llm_attempt_duration_seconds (single upstream attempts, by path+outcome) — to feed the P95/P99 sizing work that #220 defers. It replaces the four hardcoded 90s refine contexts with a REFINE_TIMEOUT env override (refine_budget.go) clamped to [1s, 30m] against wrong-unit and duration-overflow typos, keeping the 90s default. It tags the document-preview generation call (document_preview) and the three reduce-by-person worker wrappers (worker_reduce) that previously landed in unknown. Finally it documents why PerModelTimeout is deliberately NOT armed on the service entry points — the arming hunk from the first commit was dropped in follow-up 33a40bb. Overall: a careful, defensive change; histogram math, clamp logic, and path propagation all verified end-to-end, and no P0/P1 issues found.
Verification
Static analysis only at head 33a40bb0; build and tests not executed in this environment (review protocol forbids running them here; the PR ships its own test coverage, described below).
- ✅ Histogram bucket semantics —
sort.SearchFloat64satinternal/llmobs/metrics.go:196returns the first boundary >= v, so a sample exactly ON a boundary counts into that bucket (correct inclusive-lesemantics); over-range samples still reach_sum/_countand+Inf(:198-202); negatives clamp to 0 (:191). - ✅ Concurrency —
observemutates underh.mu;writesnapshots under the same lock and renders after unlock (metrics.go:207-228); the bucket slice is defensively copied innewHistogramVec(:180-182) and never mutated, so the lock-free read inwriteis safe. - ✅ Bounded cardinality — runDur labels = path only (
metrics.go:374); attemptDur = path+outcome (:334-337); both from closed constant sets; series = paths × (12 buckets + 3). - ✅ No naming collision —
llm_run_duration_secondscannot collide with the pre-existingllm_call_duration_seconds_totalunder OpenMetrics family normalization; no existing series renamed or removed, so existing dashboards keep working. - ✅ REFINE_TIMEOUT parse/clamp — wrong-unit (
90000→ clamped 30m), int64-max (no negative wrap), non-numeric/float/duration-string/zero/negative (→ default 90s) all pinned byinternal/api/handler/refine_budget_test.go; warning uses%q, so log-injection-safe. - ✅ Refine parity — all four call sites converted (
internal/api/handler/edit.go:277,:444,internal/api/handler/personal_refine.go:110,:336); grep confirms no remaining90 * time.Secondoutside the default constant. - ✅ Path propagation —
callStreamWithModel/callWithPolicyAndModelbuildllmfallback.ConfigwithoutPath, so the context value wins (internal/llmfallback/context.go:27); the document_preview tag set atinternal/api/handler/document_preview.go:318reachesRunintact. - ✅ Duration data sources — every
ObserveAttempt/ObserveResultemission fillsDuration: time.Since(...)(internal/llmfallback/fallback.go:136/:147/:172/:183/:202/:327), so both histograms receive real non-negative wall-clock on every terminal path, including cancel/timeout and the empty-model-list error path.
Findings
No P0/P1 issues; two nits below.
Nit — PR title overstates what ships (internal/service/llm.go:270)
The title/branch says "arm the fallback deadline guard", but the final diff deliberately leaves PerModelTimeout unset — the arming hunk was dropped in 33a40bb and replaced by this explanatory comment, and CONFIGURATION.md:21 now documents that the guard is active on agent chat and tool calls only. Code and docs are correct and self-consistent; only the title may mislead changelog readers. Suggest retitling, e.g. "histogram for LLM call latency + REFINE_TIMEOUT override".
Nit — Unreachable branch + shared warn-once, both as documented (internal/api/handler/refine_budget.go:87)
(1) d < minRefineTimeout is unreachable: the secs <= 0 gate at :76 already guarantees secs >= 1, hence d >= 1s == minRefineTimeout — pure defense. (2) The single shared sync.Once at :58 covers all three warning branches, so if REFINE_TIMEOUT moved between deviation classes within one process lifetime, only the first class would log. Both match the documented "logged once per process" contract; no change required.
Things I checked that are fine
document_preview.gohunk is pure closure re-indentation plusWithPath; the SSE delta logic is byte-identical, and the handler has exactly one LLM call.parseExpositionchange inmetrics_test.goresolves_bucket/_sum/_countsamples to the base family only when its TYPE is histogram; no existing counter/gauge name ends in those suffixes, so legacy assertions are unaffected.- New tests drive the real public surface (
NewMetrics→ObserveResult/ObserveAttempt→WritePrometheus) with exact cumulative assertions, a race test, and a negative-clamp test — no hand-fed internal state bypassing the production path. - Guard-arming surface is exactly as documented:
PerModelTimeoutset only atinternal/service/llm.go:569(tool calls) andinternal/agent/llm.go:101(agent chat); worker Map/Reduce roots at deadline-lesscontext.Background()(internal/worker/processor.go:739), confirming the new comment's claim that the guard would be inert there. - Per-attempt cap remains
http.Client{Timeout: LLM_TIMEOUT}(internal/service/llm.go:89), unchanged; attempt-vs-run divergence the help texts describe is therefore real and correctly attributed.
Data-flow trace (per consumed datum)
e.Duration(histogram input) ←time.Since(start)/time.Since(attemptStart)at every emission site ininternal/llmfallback/fallback.go— always populated, monotonic, non-negative; flows toobserve()on all terminal paths (success, terminal, exhausted, cancel, timeout, misconfiguration).pathlabel ←cfg.pathFor(ctx)=Config.Path(tool_call only) elsePathFromContext; this PR sets it at the four refine handlers, the three reduce-by-person wrappers (internal/service/llm.go:951/:958/:966), and the document-preview handler (internal/api/handler/document_preview.go:318); everything else staysunknown. No intermediateWithPath/Config.Pathoverride exists in any of those chains.refineTimeout()result ←REFINE_TIMEOUTenv (TrimSpace → Atoi → clamp) or 90s default →context.WithTimeoutat the four refine sites → parent deadline forllmfallback.Run; per-attempt cap unchanged (LLM_TIMEOUT via http.Client).h.buckets← defensive copy ofdurationBucketsinnewHistogramVec; immutable after construction; consumed by the boundary search and the render loop.
Blind-spot checklist (C1–C6)
- C1 dual-path parity — clear. Streaming/non-streaming refine pairs both converted (edit.go x2, personal_refine.go x2); Call/CallStream entry points both leave
PerModelTimeoutunset with mirrored comments (internal/service/llm.go:270/:412); reduce-by-person WithModel variants were already tagged at base — this PR completes the three untagged wrappers. - C2 control-flow ordering / nested reuse — clear.
refineTimeout()is invoked independently at four sites (no nesting, no double application); parse probed with non-canonical inputs ("+90" accepted as 90 — safe; "1_800", "0x708", unicode digits rejected → default — safe). - C3 authorization boundary vs capability — N/A: no auth/permission/tool/credential changes in the diff.
- C4 authorization lifecycle / container cascade — N/A: no authorization or container/member status logic touched.
- C5 build/note pass ≠ runtime correctness — clear with stated caveat: no packaging/build artifact changes; runtime paths were traced end-to-end (emission → observe → render; env → clamp → context deadline) rather than relying on "tests exist"; per protocol, builds/tests were not executed in this environment.
- C6 governance/docs self-consistency — clear.
CONFIGURATION.md:21and:53cross-checked against code (default 90s, clamp [1s, 30m], guard-active scope,llm_run_duration_secondsnaming); consistent with unchanged rows (LLM_TIMEOUT=180, AGENT_STEP_TIMEOUT sizing advice).
Cross-round blocker re-check (R6)
N/A — no prior review round exists on this issue; nothing outstanding to re-verify.
Verdict: APPROVED
The histogram implementation is mathematically correct (boundary-inclusive buckets, cumulative rendering, +Inf/sum/count consistency, outlier retention), concurrency-safe, and cardinality-bounded; the REFINE_TIMEOUT override is clamped against exactly the two failure modes that parse cleanly but break production (wrong unit, duration overflow) while preserving the historical 90s default; all four refine call sites and every path-tagging site are wired consistently; and every datum feeding the new series was traced back to its emission point. Two nits, neither blocking.
[Octo-Q] verdict: APPROVE — zero P0/P1 at head 33a40bb; histogram math, REFINE_TIMEOUT clamp, four-site parity, and emission→render data flow all verified end-to-end; only two non-blocking nits (stale PR title vs dropped arming hunk; informational refine_budget notes). Recommend the terminal review approve if it concurs with the trace above.
Both blockers from the re-review are documentation defects introduced by
the previous commit's revert, and both assert something the shipped code
does not do.
## P1 (Jerry-Xin) — the refine sizing formula was stale after the revert
refine_budget.go and CONFIGURATION.md both stated
REFINE_TIMEOUT >= 2 * LLM_TIMEOUT + backoff
That held only under the budget-guard behaviour the previous commit
reverted, where the primary was abandoned after its first retry. With the
guard unarmed, Run gives the primary all MaxAttempts (3) attempts before
considering another model: a hanging attempt is cut by http.Client.Timeout
and classifies RetrySameModel, so it costs a full LLM_TIMEOUT and the loop
continues. Only when the parent deadline fires inside an attempt does it
classify Terminal, and then Run returns with no fallback attempted at all.
Real thresholds at defaults:
fallback gets one complete attempt >= (MaxAttempts+1)*LLM_TIMEOUT + backoffs = 723s
fallback cannot start at all < MaxAttempts*LLM_TIMEOUT + backoffs = 543s
An operator sizing to the documented 363s would have landed squarely in the
second regime while believing they were in the first — the exact failure the
same row warns about. Both texts now carry the real arithmetic, note that
the 90s default is in the unreachable regime deliberately, and record why
the old number was wrong so it does not get restored.
## P1 (yujiawei) — "and tool calls" was false on every production caller
The rewritten guard-scope sentence claimed the escalation guard is active
on "agent chat and tool calls only". Tool calls do set PerModelTimeout
(service/llm.go:569), but the guard is additionally gated on the PARENT
context carrying a deadline, and CallWithTools' only callers are the worker
pipeline closures (worker/processor.go:755, personal_processor.go:706) over
the deadline-less context.Background() at processor.go:739. Nothing in
between adds a deadline.
Agent chat is the only live path: PerModelTimeout at agent/llm.go:101 plus
a real parent deadline from runner.go:156. The sentence now says so, with
the per-path exclusion reasons.
This one stings: the pre-PR text was correctly scoped to agent chat and
this PR broadened it. Someone picking up Mininglamp-OSS#220 §2 would have read
"tool calls: armed" and skipped a path that needs the aggregate deadline.
## Also addressed
- P2-1: tag the two CallRaw sites (PostRetrievalNarrow) with a new
PathWorkerNarrow. Runs on every worker task, so it was real recurring
traffic sitting in path="unknown" — the same class of gap the previous
commit fixed for document_preview.
- P2-2: CONFIGURATION.md no longer calls REFINE_TIMEOUT a "total request
deadline". Both streaming handlers clear the response write deadline, so
it bounds the LLM run, not the request. Predates this PR; worth its own
issue.
- P2-3: llm_attempt_duration_seconds HELP now states it is right-censored
at LLM_TIMEOUT — sound for deciding to lower the cap, useless for
deciding what raising it would recover.
- P2-4: the cardinality comment now includes outcome in its own arithmetic
(~480 series vs runDur's 120) instead of reading as if path were the
only dimension.
- P2-5: deprecation note on llm_call_duration_seconds_total, which is now
exactly llm_run_duration_seconds_sum from the same ResultEvent.Duration.
- Nits: dropped the unreachable minRefineTimeout branch; ParseInt(.., 64)
instead of platform-width Atoi so the overflow row is architecture-
independent; corrected the preview route to /api/v1/...; unset row in
the parse table now pins against an ambient REFINE_TIMEOUT; stale test
doc comment fixed; added a row asserting 723s is expressible.
Verification:
CGO_LDFLAGS=-L/home/mlamp/.local/lib go test -race -count=1 ./... PASS
CGO_LDFLAGS=-L/home/mlamp/.local/lib go vet ./... PASS
git diff --check PASS
Refs Mininglamp-OSS#231, Mininglamp-OSS#220
|
Both P1s were real and both were mine — pushed P1 (@Jerry-Xin) — stale sizing formula
Corrected in
Your point about the 363s trap is what makes this blocking rather than cosmetic: it puts the operator in the second regime while the text promises the first. The comment now records why the old number was wrong, so it doesn't get restored by someone reading the guard code in isolation. The 90s default staying in the unreachable regime is now stated outright rather than implied. P1 (@yujiawei) — "and tool calls" was falseConfirmed your call-graph walk. The part I want to name explicitly: the pre-PR sentence was correctly scoped and I broadened it. Someone picking up #220 §2 would have read "tool calls: armed" and skipped a path that needs the aggregate deadline. Now P2s taken in this commit
NitsDropped the unreachable TitleAlready retitled to Still open#220 §2 (the aggregate worker deadline, ~18–27 min worst case against a ~10-min scanner and 20-min lease) remains untouched and is the single most important follow-up — the reverted hunk was the only thing gesturing at it. I'll open a dedicated issue referencing #220 §2 so it can't get lost, since #220 bundles five separate problems.
|
yujiawei
left a comment
There was a problem hiding this comment.
Code Review — PR #232 (octo-smart-summary)
Reviewed at head da8e819, against merge-base eb9e0e3. I checked the branch out and ran locally (go1.26.5):
go build ./... OK
go vet ./internal/llmobs/... ./internal/api/handler/... ./internal/service/...
./internal/llmfallback/... ./internal/worker/... OK
go test -race -count=1 ./internal/llmobs/... ./internal/llmfallback/...
./internal/api/handler/... ./internal/service/... PASS
CI on this head is green except check-sprint (project-board automation, unrelated to the diff).
I also rendered the real exposition output from a scratch test to check the histogram end-to-end rather than trusting the unit assertions:
llm_run_duration_seconds_bucket{path="document_preview",le="300"} 1
llm_run_duration_seconds_bucket{path="document_preview",le="+Inf"} 2
llm_run_duration_seconds_sum{path="document_preview"} 400.1
llm_run_duration_seconds_count{path="document_preview"} 2
llm_call_duration_seconds_total{path="document_preview"} 400.1
The 400s sample reaches +Inf/_sum/_count and no finite bucket, the cumulative counts are right, and the deprecated counter really is byte-identical to the histogram's _sum — which is what the new HELP text claims.
The previous round's blocker is genuinely fixed. The 2 * LLM_TIMEOUT + backoff formula is gone and both its replacements are correct against the source, which I traced rather than took on faith (details in §1). Nothing in this round rises to a blocker.
1. Spec compliance
Result: met.
| Stated change | Status |
|---|---|
llm_run_duration_seconds{path} — whole-Run wall-clock |
Implemented as described |
llm_attempt_duration_seconds{path,outcome} — single attempt |
Implemented as described; AttemptEvent.Duration was indeed already delivered and discarded |
REFINE_TIMEOUT, default unchanged at 90s, clamped [1s, 30m] |
Implemented; default pinned by a test |
PathDocumentPreview on the live preview route |
Implemented (document_preview.go:318); that route's only CallStream site, verified by grep |
PathWorkerNarrow on the worker's post-retrieval narrowing |
Implemented; verified below |
Three CallReduceByPerson* variants tagged |
Implemented; the "no production caller today" claim still holds — CallReduceByPersonStreamWithModel (internal/worker/meta_processor.go:235) is the only wired one and was already tagged |
PerModelTimeout arming reverted, replaced by recorded reasoning |
Implemented (internal/service/llm.go:270-286, :412-414) |
CONFIGURATION.md rows |
Implemented |
No missing work, no scope violations. Behaviour at defaults is unchanged: with REFINE_TIMEOUT unset, refineTimeout() returns defaultRefineTimeout and all four handlers build the same 90s context they built before.
Claims I verified rather than accepted
The 723s / 543s sizing formulas are correct. With PerModelTimeout unset, the guard at internal/llmfallback/fallback.go:306 (if hasNext && cfg.PerModelTimeout > 0) is unreachable, so runModel spends the full MaxAttempts budget. A hanging attempt is cut by http.Client.Timeout (internal/service/llm.go:89, single client shared by streaming and non-streaming) and internal/service/llm.go:317-322 classifies it RetrySameModel because the parent context is still alive — so it costs a full LLM_TIMEOUT and the loop continues. Default backoffs are backoff(1)+backoff(2) = 1s+2s = 3s. Primary exhaustion is therefore 3*180+3 = 543s, and one complete fallback attempt needs 4*180+3 = 723s. Both numbers check out.
"The early-escalation guard is active on agent chat only" is correct. PerModelTimeout is set in exactly two places: internal/agent/llm.go:101 (PathAgentChat, and internal/agent/runner.go:156 gives that call a real StepTimeout deadline) and internal/service/llm.go:569 (PathToolCall), whose only callers are internal/worker/processor.go:756 and internal/worker/personal_processor.go:707 — both rooted at context.Background() (processor.go:740), no deadline. The agent tool paths (tool_merge_summaries.go:174, tool_narrow_channels.go:58, tool_summarize_chunk.go:508) go through callWithPolicyAndModel, which sets no per-attempt budget. So the sentence is accurate on every branch.
The refine rationale for not arming is correct. With PerModelTimeout=180s and a 90s parent, a fast first failure leaves ~89s, which satisfies remaining > delay && remaining < delay+2*PerModelTimeout (89 < 361) — the guard would fire on every first retry, exactly as the comment says.
The worker path tag lands where the comment claims. Both llmFn closures reach pipeline.ResolveAndFetchMessagesForPersonal (processor.go:798, personal_processor.go:735), and inside it llmFn is consumed at exactly one site, internal/pipeline/fetch.go:991 → PostRetrievalNarrow. It is not the same closure NarrowByTopicReport takes, so worker_narrow is not silently absorbing channel narrowing. No existing tag is shadowed: CallRaw → Call → callWithPolicyAndModel sets no Config.Path, so pathFor falls through to the context value.
2. Code quality
Result: Approved.
The histogram is careful work. The boundary search is right — sort.SearchFloat64s is a lower bound, so a sample exactly on a boundary lands in that bucket, which is what le (≤) requires; over-range samples touch no finite bucket but still reach +Inf/_sum/_count; cumulation happens at render time so observe stays O(1) on the update; the write path snapshots under the lock and formats outside it; formatBucket uses the same 'g'/-1 rendering the reference client does. The bucket slice is copied on construction, which is the kind of defence that only looks paranoid until someone sorts the package-level slice elsewhere. No naming collision is introduced: under OpenMetrics normalization llm_call_duration_seconds_total → llm_call_duration_seconds, which does not meet llm_run_duration_seconds.
The tests assert exact cumulative values rather than "a bucket moved", which is the difference between catching an off-by-one and not. refine_budget_test.go covers the two rows that actually matter (wrong-unit and int64-overflow) and asserts the invariant — always a usable positive deadline — on every row, not just the interesting ones. No test in internal/api/handler calls t.Parallel(), so the t.Setenv table carries no flake risk.
The findings below are all non-blocking.
P2-1 — llm_run_duration_seconds cannot resolve the region it is advertised to size
internal/llmobs/metrics.go:161:
var durationBuckets = []float64{0.5, 1, 2, 5, 10, 20, 30, 60, 90, 120, 180, 300}The HELP text sells this series as the tool for sizing parent budgets:
Use it to size PARENT budgets (REFINE_TIMEOUT, AGENT_STEP_TIMEOUT)
and CONFIGURATION.md sends the operator here to decide whether to raise REFINE_TIMEOUT. But the top finite boundary is 300s, and the parent budgets under discussion live past it:
- the fallback-reachable refine budget this PR documents is 723s, and
REFINE_TIMEOUTaccepts up to 1800s; - worker runs carry no deadline at all — the PR's own out-of-scope note puts worst-case worker fallback latency at ~18–27 min.
So for path="worker_map" / worker_reduce, and for any refine deployment that takes the PR's own advice and raises the budget, everything interesting collapses into +Inf and histogram_quantile returns the last boundary or +Inf for P95/P99. The right-censoring caveat in the HELP text is attached to llm_attempt_duration_seconds (where it is fine, since LLM_TIMEOUT defaults to 180s < 300s) — llm_run_duration_seconds carries no equivalent warning and is the series with the wider distribution.
Two extra boundaries (say 600, 1800) would cover it. Worth doing in this PR by the same argument the PR makes for the metric name — cheap before dashboards exist. I am not blocking on it: adding boundaries later is backwards-compatible for histogram_quantile (unlike a rename), _sum/_count and the +Inf count remain correct in the meantime, and no existing behaviour is wrong.
P2-2 — the attempt-histogram HELP is wrong for path="tool_call"
internal/llmobs/metrics.go:316:
Use it to size the per-attempt
LLM_TIMEOUT; … every attempt is already capped by the currentLLM_TIMEOUT
That holds for agent_chat / agent_tool (internal/agent/llm.go:51, built from h.llmTimeout at internal/api/handler/agent_chat.go:181) and for everything on the shared http.Client (internal/service/llm.go:89). It does not hold for tool_call, which caps each attempt with a different knob:
// internal/service/llm.go:602
attemptCtx, cancel := context.WithTimeout(ctx, c.toolCallTimeout)TOOL_CALL_TIMEOUT defaults to 30s, so llm_attempt_duration_seconds{path="tool_call"} piles up at le="30" and an operator following the HELP text would tune LLM_TIMEOUT from a series that LLM_TIMEOUT does not govern. One clause naming the exception fixes it.
P2-3 — the cardinality arithmetic in the comment no longer matches the code
internal/llmobs/metrics.go:338-341:
// = 8 x 4 x 15 = ~480 series for this family, against 8 x 15 = 120 for
// runDur.After this PR there are nine Path constants (internal/llmfallback/observer.go:11-26 — the two new ones plus unknown), so the real figures are 9 × 4 × 15 = 540 and 9 × 15 = 135. outcomeLabel (metrics.go:400-413) also has a fifth "unknown" arm, unreachable today but part of the label domain. The comment exists specifically so the next person adding a label sees the true cost, which makes stale arithmetic worth a one-line fix.
P2-4 — CONFIGURATION.md is looser than the source comment it summarises
CONFIGURATION.md:21:
a fallback is reachable only at
(MaxAttempts+1) * LLM_TIMEOUT + backoffs(723s at defaults)
refine_budget.go:30-32 is precise about this — it distinguishes "fallback gets one complete attempt" (≥723s) from "fallback cannot start at all" (<543s), correctly leaving the 543–723s band as a partial attempt. "Reachable only at 723s" flattens that: between 543s and 723s a fallback is reached, just with a truncated budget, and a fast-answering fallback can still succeed there.
This errs on the safe side — an operator following it over-provisions rather than under-provisions, the opposite of the defect the last round blocked on — so it is a wording fix, not a blocker. Matching the doc row to the source comment's two-regime phrasing would close it.
P2-5 — deprecating a live metric is not mentioned in the description
internal/llmobs/metrics.go:296 rewrites the HELP of the existing counter to open with DEPRECATED, prefer llm_run_duration_seconds. The reasoning is sound and I verified the underlying claim (the counter and the histogram's _sum are fed from the same ResultEvent.Duration and agree to the last digit in the dump above). But this is an operator-visible deprecation of an existing published metric — it shows up in the scrape and in every metric browser — and the "Change" section does not mention it. Worth a line in the PR description so whoever owns the dashboards sees it, especially since no removal timeline is stated.
Nits
CONFIGURATION.md:21, guard scope: the guard also requires a next model (fallback.go:306,hasNext), so withLLM_FALLBACK_MODELSempty — the default — it is inert even on agent chat. Implicit from the row it lives in, but a parenthetical would make it exact.refine_budget.go:80: one process-widesync.Onceis shared by the reject and clamp branches, so a second, different misconfiguration is silent. Fine for a value read from a fixed environment; noting it becauserefineTimeout()re-reads the env per request, which invites the assumption that it re-reports too.- The test helper
parseExpositionvalidates structure, not Prometheus grammar — it would accept duplicate labels or misplaced braces. Pre-existing, and out of scope here, but apromtool check metricsstep over the rendered output would be a cheap real guard for a hand-written renderer.
3. Verdict
APPROVED.
No P0/P1. Behaviour at defaults is unchanged, the histogram math is verified correct against rendered output rather than only against its own assertions, and every load-bearing claim in the new comments and docs — the 723s/543s formulas, the guard-scope statement, the path-tag routing, the no-production-caller claim — traces cleanly to the source. The five P2s are resolution and documentation-precision items; P2-1 and P2-2 are the two I would most like to see folded in, either here or as an immediate follow-up.
4. Coverage — what I did not check
- No live Prometheus or
promtoolvalidation of the rendered exposition; correctness is argued from the format spec and an eyeballed dump, not from a real scraper. - No load or GC-pressure measurement of the per-scrape snapshot copying in
histogramVec.write; fine at the current label counts, unverified at scale. - No runtime exercise of the four refine handlers with a non-default
REFINE_TIMEOUT—refineTimeout()is unit-tested, but the handler wiring is verified by reading, not by driving the endpoints. - No cross-check against the other open PRs on this repo for post-merge semantic conflict; none of them appear to touch
internal/llmobs,internal/llmfallback, orinternal/service/llm.go, but I did not build any merged combination. - Sub-0.5s resolution is absent from both histograms by construction; I did not assess whether any path's real distribution sits low enough for that to matter in practice.
Jerry-Xin
left a comment
There was a problem hiding this comment.
Code Review — PR #232 (octo-smart-summary) — re-review at da8e8199
Verdict: APPROVE. Re-review at head da8e8199838d, single new commit da8e819 ("docs(obs): correct the refine budget formula and the guard-scope claim") vs previously reviewed head 33a40bb0. Verified locally: byte-level delta diff, independent recomputation of the budget arithmetic from code constants, a full call-graph walk of the guard arming sites, and go build / go vet / go test -race -count=1 on all four touched packages (all green).
1. Prior-round blockers and peer findings — all fixed
Formula mismatch (my prior 🔴). Fixed in all three places, and I recomputed the arithmetic from code rather than trusting the new text:
MaxAttempts: 3hardcoded atinternal/service/llm.go:289,:417,:570andinternal/agent/llm.go:102LLM_TIMEOUTdefault 180 (internal/config/config.go:210)- Backoff
2^(attempt-1)seconds (internal/llmfallback/fallback.go:109-114): 1s + 2s = 3s across the 3 primary attempts - Guard-less worst case: primary consumes 3×180+3 = 543s; one complete fallback attempt needs 543+180 = 723s ✓
refine_budget.go:28-37, both CONFIGURATION.md rows (LLM_FALLBACK_MODELS, REFINE_TIMEOUT), and the PR body (723s/543s table) now all state this correctly, including the second regime (< 543s the run ends Terminal with no fallback attempt at all). The old 2*LLM_TIMEOUT + backoff survives only as an explicit historical note. ✓
Guard-scope claim (my prior 🟡; yujiwei's P1 🔴). Fixed. CONFIGURATION.md now says the guard is "active on agent chat only", with a per-exclusion reason, each byte-verified:
- Agent chat:
PerModelTimeoutatinternal/agent/llm.go:101+ a real parent deadline (context.WithTimeout(ctx, r.policy.StepTimeout)atinternal/agent/runner.go:156) → guard live ✓ CallWithToolssetsPerModelTimeout: c.toolCallTimeout(internal/service/llm.go:570), but every production caller is the worker pipeline rooted atcontext.Background()(internal/worker/processor.go:740; personal pipeline likewise) with no deadline added anywhere down the chain →ctx.Deadline()returnsok==false, guard cannot fire ✓Call/CallStreamdeliberately leavePerModelTimeoutunset (internal/service/llm.go:270-286) → inert on worker Map/Reduce and API refine ✓
Observer path comment (my 🟡). Fixed: /api/v1/summaries/document/preview now matches the mounted group (internal/api/router/router.go:76 + :177). ✓
Unreachable branch (my 🟡). Fixed: the d < minRefineTimeout branch and the minRefineTimeout constant are removed. Confirmed genuinely unreachable — secs <= 0 is rejected first, so secs >= 1 and d >= 1s always. ✓
yujiwei's title 🔴. Fixed: PR title is now "feat(obs): run + attempt latency histograms, configurable REFINE_TIMEOUT" — the "arm the guard" wording is gone. ✓
yujiwei's remaining P2s and nits (all marked optional/follow-up, all addressed anyway). P2-1 CallRaw tagging → done via the new PathWorkerNarrow + WithPath on both worker closures (the exact worker_narrow name the review suggested); P2-2 "Total request deadline" → now "LLM budget … does not bound the HTTP request", correct given SetWriteDeadline(time.Time{}) at edit.go:429 / personal_refine.go:321; P2-3 right-censoring → attempt HELP now says "CENSORED ON THE RIGHT"; P2-4 cardinality reasoning → arithmetic comment added; P2-5 duplicate counter → HELP now starts "DEPRECATED, prefer llm_run_duration_seconds"; stale metrics_test.go comment and the ambient-REFINE_TIMEOUT test defense (t.Setenv+os.Unsetenv) → done.
2. Delta hunk inventory — the commit is NOT docs-only (non-blocking)
The commit is titled docs(obs) but contains three executable changes; each verified safe, and the first two implement prior-round review asks:
| Hunk | Class | Assessment |
|---|---|---|
refine_budget.go comment expansion |
comment-only | ✓ accurate |
refine_budget.go Atoi→ParseInt(raw,10,64) + minRefineTimeout clamp removal |
executable | Safe: identical on 64-bit; on 32-bit builds int64-overflow values now clamp instead of defaulting (architecture-independent parse table, as the prior nit requested); removed floor clamp was unreachable |
refine_budget_test.go (os import, setenv/unsetenv rework, 723 row, ceiling assertion) |
test-only | ✓ |
llmfallback/observer.go route comment |
comment-only | ✓ |
llmfallback/observer.go new PathWorkerNarrow const |
executable | Safe: label-only; no switch/control flow branches on Path anywhere |
llmobs/metrics.go HELP strings |
runtime string (exposition text only, no samples) | ✓ |
worker/processor.go / personal_processor.go WithPath(ctx, PathWorkerNarrow) on the two CallRaw sites |
executable | Safe: metric attribution moves unknown→worker_narrow; implements prior-round P2-1 verbatim |
🟡 Non-blocking note: these runtime changes (a new metric label on every path-labelled family, plus parse hardening) ship under a docs(...) commit title. They are benign and reviewer-requested, and a squash merge preserves the (accurate) PR title, so this is not a merge blocker — but if this lands via merge/rebase, please amend the commit message first so git log doesn't hide a metric-label change behind a docs title.
3. Tests and CI
go build ./internal/...,go vet ./internal/...: clean (the cmd/ link step needslibtokenizers, as in CI)go test -race -count=1:internal/api/handlerok (35s),internal/workerok,internal/llmobsok,internal/llmfallbackok- CI at
da8e8199: Build / Lint / Test / Test (race, cgo) / Vet / dependency-review / osv-scan / gitleaks / pr-title-lint all pass;check-sprintfails with "No linked issue found — add a 'Closes #' reference" (process gate, not in the ruleset's required-check list, but please fix it);code-reviewpending.
Merge gate (ruleset "main branch protection", id 16278120): requires 2 approvals + code-owner review + last-push approval + all review threads resolved + the code-review status check + linear history. mergeable=true (no conflicts); the blocked state is purely the approval/thread/check requirements above.
Cross-PR: no symbol collisions — this head's new identifiers live in llmfallback/llmobs, which no other open PR touches (#233 only overlaps router.go, untouched here). #209/#214 overlap internal/worker/personal_processor.go textually but in disjoint regions (finalize / citation cap vs the llmFn closure) — ordinary merge-order resolution, nothing to do now.
4. Remaining nits (non-blocking)
- The new cardinality comment in
internal/llmobs/metrics.gosays8 x 4 x 15 = ~480series for attemptDur — but this same commit adds the 9th path (worker_narrow), so it is now9 x 4 x 15 = ~540(and9 x 15 = 135for runDur). The conclusion ("affordable; a third dimension likely is not") is unchanged; please correct the numbers next time the file is touched. 723sis the idealized arithmetic floor (request setup/classification overhead is small but non-zero); operators sizingREFINE_TIMEOUTshould leave some headroom rather than dialling exactly 723. Optional wording polish.check-sprintis red: add theCloses #<issue>linkage to the PR body (or have a maintainer assign the sprint on the board).
Jerry-Xin
left a comment
There was a problem hiding this comment.
APPROVE on da8e819.
Re-review of the fix commit docs(obs): correct the refine budget formula and the guard-scope claim, byte-verified against the prior head.
Prior blocking findings — all resolved
- Refine budget formula (prior 🔴):
refine_budget.gonow documents the runner's actual retry semantics: the primary receives allMaxAttempts(3) attempts before any fallback is tried, and the early-escalation guard is deliberately not armed on refine. The sizing regimes are now correct — a fallback reaches one complete attempt only whenREFINE_TIMEOUT >= (MaxAttempts+1)*LLM_TIMEOUT + backoffs= 723s at defaults, and belowMaxAttempts*LLM_TIMEOUT + backoffs= 543s a hanging primary consumes the whole budget and the run endsTerminalwith no fallback attempt at all. The old2*LLM_TIMEOUT + backofffigure is explicitly called out as valid only under the reverted budget-guard behaviour.CONFIGURATION.md(both theLLM_FALLBACK_MODELandREFINE_TIMEOUTrows) carries the same corrected arithmetic, plus the pre-existing note that on the two streaming refine handlers this bounds the LLM run, not the HTTP request. - Guard-scope claim (prior 🟡): the docs now state the guard is active on agent chat only, with the accurate reasoning — tool calls do set a per-attempt budget (
internal/service/llm.gosetsPerModelTimeoutfor tool calls), but their callers run in the worker pipeline whose context carries no deadline; worker Map/Reduce sets neither; API refine deliberately does not arm it. Verified against the call sites. - Path comment (prior 🟡):
PathDocumentPreviewcomment corrected to the full/api/v1/...route. - PR title: now reflects the PR's actual content (run + attempt latency histograms, configurable REFINE_TIMEOUT) instead of claiming the guard was armed.
Note: this commit contains code changes despite the docs(obs): prefix
All of them are safe and tested, but the label undersells the diff:
refineTimeout()drops theminRefineTimeoutfloor clamp — correct: thesecs <= 0rejection already guarantees any accepted value is ≥ 1s, so the floor branch was unreachable.strconv.Atoi→strconv.ParseInt(raw, 10, 64): removes platform-width dependence (on 32-bit builds huge values previously took the ErrRange path instead of the clamp).- New
PathWorkerNarrowmetric path, wired identically in both worker processors for the post-retrieval narrowing call, moving recurring traffic out ofpath="unknown". Bounded label set; cardinality arithmetic is documented at the observe site. refine_budget_test.goupdated accordingly (includes the documented 723s budget case).
Non-blocking (🟡)
- The commit message says
docs(obs):while the diff contains the code changes above — harmless, but the history label is misleading. - The
REFINE_TIMEOUTrow in CONFIGURATION.md still says values are "clamped to[1s, 30m]"; after the floor-clamp removal the lower bound is enforced by the ≤0 rejection (falls back to the default) rather than a clamp. Accepted range is unchanged; the mechanism wording is slightly stale.
Verification
- Full hunk inventory of
33a40bb0..da8e8199reviewed line by line; no unintended logic changes. go build,go vet, andgo test -racegreen forinternal/llmobsandinternal/llmfallbacklocally; CI (Build / Lint / Test / Vet / race) all pass on this head.- No symbol collisions with other open PRs in the touched packages.
Duplicate of 5040090701 (double-post during remediation); superseding copy dismissed.
mochashanyao
left a comment
There was a problem hiding this comment.
[Octo-Q · automated review]
Verdict: Approve — no blocking findings; notes below (data-flow traced).
Reviewer: Octo-Q (automated review)
PR: Mininglamp-OSS/octo-smart-summary #232 — feat(obs): run + attempt latency histograms, configurable REFINE_TIMEOUT
Head: da8e8199838d0af56f93c4dca609d16e95f1298a | Merge-base: eb9e0e3 (= origin/main) | Scope: 12 files +688/-25(与 GitHub PR diff 完全一致)
轮次: 第 2 轮(上轮审 33a40bb,APPROVED;本轮新增 commit da8e819 后复审)
运行说明: 本环境 skill 安装无 GLM 腿脚本(无 glm_review.py/merge_reviews.py),按降级策略单腿产出,/tmp/review.final.json 即最终 findings 源。
1. 验证结论
✅ 可合入。 全部 12 个变更文件逐一回溯,零 P0/P1/P2,仅 1 条 cosmetic Nit。静态分析(未在本环境跑 build/test;按 skill 纪律不在 checkout 内执行构建)。
- ✅ 直方图数学正确:
sort.SearchFloat64s下界搜索 ⇒le边界包含语义正确;越界样本仍计入_sum/_count/+Inf;负值钳 0;render 在锁内快照、写出时累加(internal/llmobs/metrics.go:191-268) - ✅ 事件数据流完整:
ObserveResult全部 5 个 emit 点 +ObserveAttempt唯一 emit 点均填Duration = time.Since(...)(internal/llmfallback/fallback.go:136/147/172/183/202/324),两个直方图不存在零值/缺值灌入 - ✅ 四个 refine 入口全部换用
refineTimeout()(edit.go:277/444、personal_refine.go:110/336),无遗留硬编码 90s(全仓 grep 仅剩默认值常量) - ✅
REFINE_TIMEOUT解析安全:ParseInt(_,10,64)+ 乘前溢出检查 +<=0拒绝 + 30m 上限(≥ 文档最坏 723s),每类畸形输入均降级为默认值且 once-per-process 告警(internal/api/handler/refine_budget.go:96-118) - ✅ 文档断言与代码逐条核对一致(723s/543s 公式、"guard 仅 agent chat 生效",见下 §5)
2. 发现问题
无 P0/P1/P2。
Nit — 测试用例名过期引用 Atoi(internal/api/handler/refine_budget_test.go:33):用例名 "float is rejected by Atoi",实现实际用 strconv.ParseInt(raw, 10, 64)(refine_budget.go:106 注释明确说明选 64 位显式宽度以避免 32 位平台 Atoi 行为差异)。仅命名误导,改名即可。
- diff-scope 三问:本 PR 新引入(测试文件全新);非既有行为;不触碰任何运行时路径 ⇒ Nit,不影响 verdict(R4:仅 Nit ⇒ APPROVE)。
3. 建议
- (可选)顺手把上述测试名改为 "float is rejected by ParseInt"。
- 无需其他改动;#220 后续按
llm_run_duration_seconds实测 P95/P99 再决定是否上调REFINE_TIMEOUT默认值,当前保持 90s 的决策有测试守护(TestRefineTimeout_DefaultIsUnchanged),合理。
4. 额外发现
callSecs(llm_call_duration_seconds_total)与runDur._sum同源(均在ObserveResult由同一e.Duration喂入,metrics.go:378-382),help 文本已标 DEPRECATED,dashboard 兼容期内不会分叉。- 新命名
llm_run_duration_seconds刻意避开 OpenMetrics 家族名归一化与既有llm_call_duration_seconds_total冲突(metrics.go:298-304注释),判断正确。 - attemptDur 帮助文本新增 "CENSORED ON THE RIGHT" 说明(attempt 被 LLM_TIMEOUT 截尾,顶桶是堆积不是尾部)——对运维解读是正确且必要的提示。
5. 数据流回溯(逐消费点 → 上游来源)
| 消费点 | 上游来源 | 是否真流到 |
|---|---|---|
runDur.observe (metrics.go:382) |
ResultEvent.Duration ← time.Since(start),Run 的全部 5 个退出路径均填 |
✅ |
attemptDur.observe (metrics.go:344) |
AttemptEvent.Duration ← time.Since(attemptStart),runModel 每次 attempt 后唯一 emit(fallback.go:324-327),含 Success/Terminal/TryNextModel/RetrySameModel 全部分支 |
✅ |
path 标签 |
cfg.pathFor(ctx):Config.Path 在 diff 涉及的全部 Run 调用点均未设置 ⇒ ctx 标签生效(context.go:59-62)。WithPath 注入点:worker narrow 两处 CallRaw(→Call→callWithPolicyAndModel→Run)、document_preview CallStream(→callStreamWithModel→Run)、reduce-by-person 三个入口(→callDisclosingTerminalReduceWithModel/callStreamWithTruncationNotice→Run) |
✅ 每条链逐跳确认 |
refineTimeout() 返回值 |
四个调用点全部喂给 context.WithTimeout 作为父截止时间 |
✅ |
| 文档 723s/543s 公式 | runModel 语义:primary 独占 MaxAttempts=3 次(fallback.go:298 循环);挂起 attempt 被 http.Client.Timeout 切断 ⇒ RetrySameModel 续跑(service/llm.go:317-322:仅 ctx.Err()!=nil 才 Terminal);默认 backoff 1s+2s=3s ⇒ 543s 后 fallback 才可能启动,723s 才够 fallback 完整一次 |
✅ 公式与代码一致 |
| "guard 仅 agent chat 生效" | PerModelTimeout>0 且 ctx 带 deadline 才激活(fallback.go:306-315)。PerModelTimeout 仅两处:service/llm.go:569(CallWithTools,调用方 worker 两处理器均 context.Background() 无 deadline ⇒ 惰性)+ agent/llm.go:101(agent chat,runner.go:156 StepTimeout deadline ⇒ 激活)。agent 工具走 CallStrict/Call 链,不设 PerModelTimeout |
✅ |
| worker narrow "每个任务都跑" | executePipeline(processor.go:763-769)与 executePersonalPipeline(personal_processor.go:716-722)的 PostRetrievalNarrow llmFn;全仓 CallRaw 仅这两处,无漏标兄弟 |
✅(C1 成对核验) |
6. 盲点 checklist
- C1 双路径 parity — CLEAR:4 个 refine 入口全换
refineTimeout();2 个CallRaw全标PathWorkerNarrow;4 个 reduce-by-person 变体全标PathWorkerReduce(第 4 个变体 base 已有标签);无遗漏兄弟。 - C2 control-flow ordering / 复用 — CLEAR:
refineTimeout()为纯函数、四处复用行为一致;guard 条件在嵌套复用下不会被二次触发(仅 runModel backoff 前检查一次/轮)。无正则/escape 类控件改动。 - C3 授权边界 — N/A:本 PR 无权限/endpoint 暴露变更(文档预览路由为既有,仅加 ctx 标签)。
- C4 授权生命周期/级联 — N/A:同上,无鉴权改动。
- C5 build/运行期 — CLEAR:无构建/打包改动;
/metrics暴露面为既有(PR#219 引入,llmobs.Install双 cmd 装配),本 PR 仅新增两个家族进WritePrometheus。 - C6 治理/文档自洽 — CLEAR:CONFIGURATION.md 新增
REFINE_TIMEOUT行与LLM_FALLBACK_MODELS行修订互相一致,且与代码行为逐条核对(默认 90、上限 30m、拒绝/钳制均 once 告警);"clamped to [1s, 30m]" 表述后半句已明确非正值回落默认,不构成误导。
7. 跨轮 blocker 复检(R6)
上轮(automated review,head 33a40bb)verdict=APPROVED,无 blocker,仅 2 条 Nit:
- Nit①(PR 标题/guard-scope 声明与实现不符)→ 已修:标题已改为 "run + attempt latency histograms, configurable REFINE_TIMEOUT"(gh pr view 确认);guard-scope 文档改为 "agent chat only" 并给出 tool-call 调用方无 deadline 的理由(§5 核验属实)。
- Nit②(
minRefineTimeout下界分支不可达)→ 已修:da8e819 删除 minRefineTimeout 常量,注释说明<=0拒绝已保证 ≥1s(refine_budget.go:75-77),测试同步更新。 - da8e819 相对 33a40bb 的新增行为(非仅文档):
PathWorkerNarrow常量 + 两个 worker 标注点 + 测试抗环境污染加固(t.Setenv+Unsetenv)——本轮已独立核验(§5)。
Code Review — PR #232 (octo-smart-summary)
Summary
This PR adds two hand-rolled cumulative latency histograms to the llmfallback observability set — llm_run_duration_seconds (whole-run wall clock by path) and llm_attempt_duration_seconds (single-attempt wall clock by path and classified outcome) — deprecates the mean-only llm_call_duration_seconds_total counter, and replaces the four hardcoded 90s refine budgets with a REFINE_TIMEOUT env knob (default 90s, ceiling 30m). It also attributes previously-unlabelled traffic: the document-preview endpoint and the worker's post-retrieval narrow calls get their own path labels, and the three remaining reduce-by-person entry points are tagged. The follow-up commit corrects the documented fallback-reachability math to the runner's real retry semantics (723s at defaults) and narrows the guard-scope claim to "agent chat only".
Verification
Static analysis only at head da8e8199; build and tests not executed in this environment.
- ✅ Histogram math —
sort.SearchFloat64sgives inclusive-leboundary semantics; out-of-range samples still land in_sum/_count/+Inf; negatives clamp to 0; rendering snapshots under the lock and cumulates buckets at write time (internal/llmobs/metrics.go:191). - ✅ Event data flow — all five
ObserveResultemit sites and the singleObserveAttemptsite fillDuration = time.Since(...)(internal/llmfallback/fallback.go:136), so neither histogram can observe a missing duration. - ✅ Path wiring —
Config.Pathis unset on everyRuncall site touched here, so the ctx tag wins:CallRaw→Call(worker narrow), theCallStreamchain (document preview), andCallReduceByPerson*(reduce). BothCallRawsites are tagged; no untagged sibling remains. - ✅ REFINE_TIMEOUT safety —
ParseInt(...,10,64)plus a pre-multiply overflow check plus<= 0rejection; the 30m ceiling clears the documented worst-case 723s budget. All four refine call sites consumerefineTimeout(); no leftover hardcoded 90s (internal/api/handler/refine_budget.go:96). - ✅ Doc claims — the 723s/543s formulas and "guard active on agent chat only" hold against
runModel:PerModelTimeoutis set only atinternal/service/llm.go:569(tool calls; worker callers carry no deadline) andinternal/agent/llm.go:101(agent chat under the StepTimeout deadline).
Findings
No P0/P1/P2 issues; one nit below.
Nit — Stale test-case name references Atoi (internal/api/handler/refine_budget_test.go:33)
The row is named "float is rejected by Atoi", but the implementation parses with strconv.ParseInt(raw, 10, 64) — deliberately, per internal/api/handler/refine_budget.go:106, to keep the width explicit on 32-bit builds. Cosmetic; rename so a future edit doesn't assume platform-width Atoi semantics.
Things I checked that are fine
- OpenMetrics family naming:
llm_run_duration_secondsavoids the_total-normalization clash with the retained counter;leis appended only on_bucketlines; label values escape through the existing helper. - Cardinality is bounded and documented (closed path enum × 4 outcomes × 15 series); attemptDur deliberately drops model/position.
- warn-once is shared across rejection/clamp classes by design, matching the documented "logged once per process".
- The streaming refine handlers' write-deadline caveat predates this knob and is now documented, not introduced.
- Prior-round nits (stale title/guard-scope claim, unreachable
minRefineTimeoutclamp) are both resolved at this head.
Verdict: APPROVED
The observability additions are exact where it matters (boundary semantics, duration sourcing, label cardinality), and the new timeout knob degrades safely on every malformed-input class with the runner's retry semantics correctly documented. The nit is cosmetic and non-blocking.
[Octo-Q] verdict: APPROVE — 零 P0/P1/P2;数据流全链回溯无断点,文档断言与代码逐条一致,上轮 2 条 Nit 均已修复,仅 1 条 cosmetic Nit(测试用例名)。建议终审放行。
|
Addendum to my review above — one more nit I missed, verdict unchanged (still APPROVED).
// internal/api/handler/refine_budget.go:97
// ParseInt with an explicit 64-bit width rather than Atoi: Atoi returns a
// platform-width int, so on a 32-bit build a value like 9223372036854775807
// would take the ErrRange path instead of being clamped, making the
// behaviour architecture-dependent.
secs, err := strconv.ParseInt(raw, 10, 64)So the row names the exact function the code was written to avoid, and the reasoning for avoiding it lives four lines above the call. Cosmetic, but worth renaming to |
Problem
llm_call_duration_seconds_total(from #219) is a cumulative sum. Divided byllm_calls_totalit yields a mean, and a mean over this workload describes no real request: refine calls are sub-second while long-context agent turns are documented at 60–100s ininternal/agent/llm.go.#220 defers the final
LLM_TIMEOUTvalue to per-scenario P95/P99 ("不直接规定LLM_TIMEOUT=60,最终值应结合各场景 P95/P99 决定"). Those percentiles require bucket counts, which no metric in the repo currently produces.Change
internal/llmobs: two latency histogramsllm_run_duration_seconds{path}— whole-Runwall-clock, including backoff sleeps and every model tried. Use it to size parent budgets (REFINE_TIMEOUT,AGENT_STEP_TIMEOUT).llm_attempt_duration_seconds{path,outcome}— a single upstream attempt. Use it to size the per-attemptLLM_TIMEOUT.The split matters:
LLM_TIMEOUTis applied per attempt (http.Client.Timeoutinservice/llm.go, the per-attempt context inagent/llm.go), but a run's wall-clock also carries backoffs and earlier models. On the happy path they coincide, so a run-level P95 is roughly usable — a run-level P99 is not, because the P99 is the retried runs.AttemptEvent.Durationwas already delivered toObserveAttemptand discarded.Buckets are fixed at package scope (0.5s → 300s) so paths stay comparable. Labels are deliberately narrow — bucket series multiply by
len(buckets)+3, somodelandpositionare left to the existing counters. Hand-rolled to match the package's existing registry; see the package doc for whyclient_golangis not used here.Named
llm_run_duration_seconds, notllm_call_duration_seconds: the latter is valid alongsidellm_call_duration_seconds_totalin text format 0.0.4, but under OpenMetrics a counter's family name is its name minus_total, so both would normalize to one family with conflictingTYPEs. Free to fix now, expensive once dashboards exist.internal/api/handler:REFINE_TIMEOUTFour call sites hardcoded a 90s parent context around a
Runwhose per-attempt timeout isLLM_TIMEOUT(180s default). A parent smaller than a single attempt means a hanging primary consumes the whole budget and no fallback attempt can start, soLLM_FALLBACK_MODELSis effectively inert on refine.The default is deliberately unchanged at 90s. Raising it changes user-visible latency on a path that errors at 90s today, and the correct value depends on the refine percentiles this PR starts collecting. What changes is that the number stops being welded into four call sites.
Values are clamped to
[1s, 30m]with a once-per-process log on rejection or clamp. Parsing alone was not enough:REFINE_TIMEOUT=90000(milliseconds assumption) parses into a 25-hour deadline, and an int64-max value overflowstime.Durationnegative, making all four handlers build an already-expired context — every refine failing instantly and silently.Path tagging
POST /api/v1/summaries/document/previewis a live wired route callingCallStreamwith noWithPath; its latency landed inpath="unknown". AddsPathDocumentPreview.CallRaw,worker/processor.goandpersonal_processor.go) was untagged and runs on every worker task. AddsPathWorkerNarrow.CallReduceByPerson,CallReduceByPersonWithModel,CallReduceByPersonStreamare tagged pre-emptively. None has a production caller today — onlyCallReduceByPersonStreamWithModelis wired (internal/worker/meta_processor.go:235) and it was already tagged. The fiveCallMap*/CallReduce*methods the worker actually uses were already tagged too, so worker attribution has been correct all along.CONFIGURATION.mdAdds the
REFINE_TIMEOUTrow and corrects theLLM_FALLBACK_MODELSrow: refine no longer has a fixed 90s deadline, and the early-escalation guard's scope is stated as agent chat only, with the reason for each exclusion.The sizing guidance is the part worth reading. With the guard unarmed,
Rungives the primary allMaxAttempts(3) attempts before considering another model, so at defaults:>= (MaxAttempts+1) * LLM_TIMEOUT + backoffs= 723s< MaxAttempts * LLM_TIMEOUT + backoffs= 543sTerminal, no fallback attemptedThe 90s default is deliberately in the second regime. An earlier revision of this PR documented
2 * LLM_TIMEOUT + backoff, which was only true under the reverted guard behaviour — sizing to that number would have put an operator in the second regime while believing they were in the first.Tests
+Inf,_sumand_count_sumpermanently)_sum, 21s run_sum)refineTimeout()parse table: unset / valid / malformed / non-positive / wrong-unit / overflow, asserting the result is always a usable positive deadline inside the clamp rangeparseExpositiontaught to resolve_bucket/_sum/_countback to their base family, as a real scraper doesVerification
No new Go modules. No new endpoints — both histograms appear on the existing
/internal/metrics, which both binaries already serve.Deliberately out of scope
The aggregate worker deadline (#220 §2). Worker LLM calls root at
context.Background()with no deadline anywhere down the chain, so worst-case fallback latency (~18–27 min with multiple models) can exceed the ~10-minute stuck scanner and the 20-minute lease, causing duplicate dispatch. That needs its own PR, together with the budget-matrix test #220's acceptance criterion 4 already asks for.Arming
PerModelTimeoutonCall/CallStream. An earlier revision of this PR did that; it was wrong in two different ways and has been reverted — see the review thread andinternal/service/llm.gofor the recorded reasoning. Arming the guard requires either the worker deadline above or a per-attempt budget derived from the remaining parent budget.The streaming refine write deadline. Both streaming refine handlers clear the response write deadline before streaming (from #157), and the server sets no
WriteTimeout, so a connected-but-not-reading client is bounded by neither.REFINE_TIMEOUTtherefore bounds the LLM run, not the request — now stated in the docs rather than fixed here.The
chunk#%dcardinality bomb.timing.RecordLLMSincereceivesfmt.Sprintf("Map: 分块总结 chunk#%d", idx)aspurpose. That value only reaches log lines today, so normalizing it now is a no-op; it must be collapsed to a boundedpurpose_classin the same PR that first feedstiminginto a metric label.Wiring
RunTrace.Report()andtiming.Record()to metrics (S3 in #231). Separate PR.Refs #231, #220