Repository navigation
perf: answer near-now label lists within a budget, at most 10s behind - #877
Conversation
⚪ Performance A/B: no change beyond noise41 shape×range — 41 ⚪ same · results vs Loki: 38 same, 0 new difference(s), 3 pre-existing Every shape is within noise of the base build (±30% and 100 ms). 41 unchanged shape×range (within noise)
Cold (first-run) timings — what a user opening a panel sees
5 shape×range above 2× Loki already (listed, or as slow on the base build)
Why these shapes
base |
✅ Visual smoke: passedBase
Gate: a base-vs-PR data difference passes when the PR is closer to Loki, and fails when the PR diverges from Loki or Loki cannot decide it (at a range Loki does not hold, a difference passes when the same page proved it closer to Loki at a shorter range; otherwise label the pull request Core set montages (5): base | PR | Lokidd-fields-1h dd-landing-1h dd-service-logs-1h explore-logs-plain-1h explore-metric-plain-1h All montages of this run: |
PR Quality ReportCompared against base branch Coverage and tests
Compatibility
Performance smokeLower CPU cost (
State
|
…most 10s old
Every Grafana refresh of /labels or /label/{name}/values ending within
-max-metadata-cache-freshness of now, once its cached answer was older than
-recent-tail-refresh-max-staleness (2s), read the near-now edge from
VictoriaLogs synchronously. The settled buckets come from the metadata
inventory, but under 32 heavy clients that edge call (stream_field_names)
waited 0.35-0.6 s at p95 and up to 2.6 s for VictoriaLogs CPU (360-470 % on
average), so /labels p95 was 50-450 ms against 5-40 ms on an idle
VictoriaLogs. The proxy never queued it; VictoriaLogs did.
Such a request now starts the refresh detached from itself and waits at
most -metadata-edge-refresh-budget (default 100ms) for it: an idle
VictoriaLogs still answers exactly. Otherwise the request gets the last
answer this replica read for the same tenant, auth scope and window, if
that read started at most -metadata-max-staleness (default 10s) ago,
marked X-Proxy-Stale-Response so the compatibility-edge and multi-tenant
caches never keep it. The refresh completes in the background (one per
cache key, sharing the listing fetch with synchronous waiters, within the
background timeout, cancelled by Shutdown) and the next request lists what
it found. Past the bound, or without such an answer, the request waits for
VictoriaLogs as before; requests ending earlier read settled data and are
never stale. Staleness is measured from the start of the VictoriaLogs read
behind the stored answer (syncFetchStringsAt returns the leader's start).
Loki lists labels from its index and ingesters
(pkg/querier/querier.go:307-342) and does not cache a metadata answer
ending within max_metadata_cache_freshness
(pkg/querier/queryrange/series_cache.go:111-125), so this bound is a
documented deviation the owner approved; -metadata-max-staleness=0 restores
exact answers. The 10s default: VictoriaLogs makes rows searchable within
about a second (lib/logstorage/datadb.go:776 in v1.49.0, :780 in v1.53.0)
and Grafana's shortest dashboard refresh is 5s. /series has no response
cache or inventory and is not affected.
The label handlers now build their answer in one closure used by both the
synchronous path and the detached refresh (the service_name values path
folds into it and keeps its own browse-window rule). A follower of a shared
listing fetch whose leader ran out of its own deadline retries, as it did
for a cancelled leader.
An empty answer (a negative entry) and a disk or peer copy are never
served stale. The e2e freshness test
(TestCompat_LabelsIncludeStreamWrittenAfterCaching) now asks again after
the bound instead of after 3 s, since within it a slow refresh may answer
from the answers read before its second stream.
Metrics: internal_operation{operation="metadata_edge_answer"} (exact,
stale, waited), {operation="metadata_edge_staleness"} (age of each stale
answer) and {operation="metadata_edge_refresh"} (background refresh).
Registry: quality/metadata-bounded-staleness (owner-kept).
The first /labels for a warmed preset after a warm-up pass still waited for its edge refresh: the warm answer was in the cache, but no read time was recorded for it, so -metadata-max-staleness could not apply. Under load that first request paid the same 0.35-2.6 s VictoriaLogs wait as an unwarmed one. warmLabelWindows now records when each window's read started, after the answer is stored (an empty answer stores nothing and records nothing), and the read skips the short-lived exact-window field-name cache like a background refresh, so the recorded start is the age of the data. The first request after a pass is then answered within -metadata-edge-refresh-budget: exactly, or from the warm answer if the warm read started within the bound. Test: after the 1h preset is warmed, the first Grafana-shaped /labels with VictoriaLogs holding its edge refresh is answered within the 50 ms budget from the warm answer, marked stale, and starts the refresh. Registry: quality/metadata-bounded-staleness.
a6d11ef to
230574e
Compare





Summary
A near-now
/labelsor/label/{name}/valuesno longer waits for a busy VictoriaLogs. The request waits at most-metadata-edge-refresh-budget(default100ms) for its edge refresh:-metadata-max-staleness(default10s) old. The refresh completes in the background, and the next request lists what it found.This is a documented, owner-approved difference from Loki, registry
quality/metadata-bounded-staleness(owner-kept).-metadata-max-staleness=0restores exact answers.Branch base:
origin/main(fc506876, v2.36.0 metadata; rebased after #746 merged, with the CHANGELOG rebuilt from main so the entries stay under[Unreleased]and the generated conformance reports regenerated), two commits:f76420cc: bounded-stale answers.a6d11efe: the label warm-up records its reads, so the first request for a warmed preset after a pass is also answered within the budget.The change needs nothing from the default-lookback PR. The branches can land in either order; whichever lands second is rebased.
A trial merge of both heads conflicts in:
CHANGELOG.md,values.yaml,cmd/proxy/main.go, theConfigcomment block inproxy.go,docs/configuration.md,KNOWN_ISSUES.md;warmLabelWindows. There, keep M1'sfetchCtx := context.WithTimeout(withBackgroundInventory(w.req.Context()), ...)and add this PR's two lines after it:labelCacheBypassKeyandreadStarted.With that resolution the merged tree builds. A throwaway test on it (not committed) shows the intended combination works: after a warm pass as tenant
1(M1's-labels-cache-warm-tenants), the first/labelsfrom tenant1for 1h, 6h and 24h, with VictoriaLogs holding the edge, is answered stale in 50-53 ms against a 50 ms budget.What was wrong
Load evidence: 32 heavy clients running 6 h range-metric shapes, plus a
/labelsprobe every 1-2 s./labelsp95stream_field_nameslatency inside VictoriaLogsThe numbers are the same on main and with the metadata lane reserving VictoriaLogs select slots. The proxy never queued a metadata call (
backend_select_lane_queued{lane="metadata"}stayed 0); the time was spent inside VictoriaLogs.The steady-state cost is the synchronous near-now edge read:
-max-metadata-cache-freshness(24h) of now counts as near-now (nearNowWindow).-recent-tail-refresh-max-staleness, which is 2 s (shouldBypassStaleEntry).metadataCacheLookup,syncFetchStrings).Loki does not lag:
pkg/querier/querier.go:307-342).max_metadata_cache_freshness(pkg/querier/queryrange/series_cache.go:111-125, used by the labels cache).Design
freshFetch) is considered. A request ending earlier than the freshness window is answered from its cached answer, as before. It is settled, never stale, and never refreshed by this path.handleLabelsandhandleLabelValuesnow build their answer in one closure. It lists, post-processes, stores the cache entry and records the read time. The synchronous path and the detached refresh both run it, so the stored answer is identical either way.labelValuesBrowseWindow).startMetadataEdgeRefresh):singleflightflight per cache key.context.WithoutCancel, so tenant, routing and auth fingerprint are kept. It runs under the background timeout (labelBackgroundTimeout, at most 10 s), from a proxy-lifetime base context thatShutdowncancels, tracked by a WaitGroup thatShutdownwaits for.sync:+key singleflight as synchronous waiters, so a request past the bound joins the running refresh instead of starting a second VictoriaLogs pass.recordMetadataEdgeRead):syncFetchStringsAtreturns the start time of the shared fetch's leader.serveMetadataEdge):X-Proxy-Stale-Response: true(markStaleResponse, which also setsCache-Control: no-store). The compatibility-edge cache (compatCacheCaptureAllowed) and the multi-tenant merge cache already skip responses with that header.warmLabelWindowsrecords when each window's read started, after the answer is stored. An empty listing stores nothing and records nothing. The warm read skips the short-lived exact-window field-name cache (labelCacheBypassKey), as a background refresh does, so the recorded start is the real age of the data./series: not included. It has no response cache and no inventory:handleSeriescalls/select/logsql/streamsdirectly through the coalescer (internal/proxy/label_handlers.go:404-440), andstreamsis not inmetadataInventoryPaths. Giving it the same treatment means adding a response cache and inventory first (follow-up).Flags and defaults
-metadata-max-staleness10slib/logstorage/datadb.go:776in v1.49.0,:780in v1.53.0). Grafana's shortest dashboard refresh is 5 s (min_refresh_interval,conf/defaults.ini:608). So a new label or value shows at most two refreshes late. It is above-recent-tail-refresh-max-staleness(2 s); a lower value adds nothing.0disables the feature.-metadata-edge-refresh-budget100ms/labelsat 5-40 ms p95, so answers stay exact when it is not busy. Under load the edge listing took 0.35-0.6 s at p95 and up to 2.6 s; the budget turns those into answers bounded by the staleness flag.0serves the last answer at once whenever one is within the bound.Both flags are declared in the config registry (
internal/config/limits.go), with bounds, metric, sizing and Loki parity ("none"). Both have HelmextraArgsvalues and rows indocs/configuration.md, anddocs/KNOWN_ISSUES.mdgains a row. The generated configuration reference and limits registry were regenerated. The flags sit in the cache category.The library
Configzero value keeps the feature off. Only the binary's flag defaults turn it on, the same pattern asMetadataCacheFreshness.Background refreshes are bounded:
Shutdowncancels them;-max-concurrent).A refresh starts only for a key this replica answered within the bound. There is no separate cap on how many keys refresh at once; whether one is wanted is an open question below.
Metrics
All are on the existing internal-operation counter and histogram. Their buckets reach 10 s, which covers the default bound.
loki_vl_proxy_internal_operation_total{operation="metadata_edge_answer",outcome="exact"|"stale"|"waited"}loki_vl_proxy_internal_operation_duration_seconds{operation="metadata_edge_staleness",outcome="labels"|"label_values"}loki_vl_proxy_internal_operation_duration_seconds{operation="metadata_edge_refresh",outcome="ok"|"error"}Tests (
internal/proxy/metadata_edge_refresh_test.go)The tests use a fake VictoriaLogs whose near-now listings can be held at a gate. "Did not wait" is proven by the gate still holding the refresh when the answer arrives, not by wall-clock time. Every request that must not wait fails the test after 5 s instead of hanging.
TestMetadataEdge_StaleWithinBudgetThenFreshOnTheNextRequest/labelsand/label/app/values, with the inventory on: the second answer is served within the 50 ms budget while the edge refresh is held at the gate. It equals the first answer and is marked stale. After the refresh completes, the next request lists the label or value that appeared meanwhile.TestMetadataEdge_PastTheBoundTheRequestWaits-metadata-max-staleness=0, or the last answer was emptyTestMetadataEdge_ConcurrentRequestsShareOneRefreshTestCompat_LabelsIncludeStreamWrittenAfterCaching(e2e, group core, changed)TestMetadataEdge_StaleAnswersStayPerTenantTestMetadataEdge_SettledWindowsAreNeverStaleTestMetadataEdge_FirstRequestAfterWarmUpAnswersWithinBudget(second commit)/labels, with VictoriaLogs holding its edge, is answered within the 50 ms budget (plus a 2 s allowance) from the warm answer, marked stale, without the label written since, and it starts the refresh. Removing the record line makes it fail.TestMetadataEdge_ShutdownStopsBackgroundRefreshesShutdowncancels a refresh held in VictoriaLogs (the fake sees its request context end), every goroutine returns to baseline, and no refresh starts afterShutdown-race:-run 'TestMetadataEdge|TestLabel.*Fresh|Freshness|TestHandleLabel|TestLabelValues|TestProxyLifecycle',-count=3) failed. The failures were in the stale-within-budget and shared-refresh tests, which checked that the background refresh had reached the fake VictoriaLogs right after the stale answer came back. Under-raceon a loaded host the refresh can reach it a little later.-raceruns (-count=3) and a-count=20run without-racepass. These were the likely causes; the original failure was not reproduced in isolation.Gates:
GOMEMLIMIT=2GiB GOMAXPROCS=4 go test -short -count=1 -p 1)../cmd/... ./internal/...): every package ok, before the rebase, on787813d0(peak RSS 1.81 GiB, 1,938,522,112 B) and on the final head0b3a2244(peak RSS 1.78 GiB, 1,911,324,672 B); origin/main 1.87 GiB (2,009,694,208 B) on the same host.go vet ./...andgo vet -tags e2e ./test/e2e-compat/: ok.check_conformance.py: conformance gate ok.check_changelog_pr.py --base origin/main: ok.go run ./cmd/configdoc -check: ok.Registry
The
why:text is in the file. It cites the Loki references above, the load numbers, the mechanism, and the owner's approval on 2026-10-27.Proof
All runs on the local Colima VM (8 CPU, 14 GB) shared with other stacks and other work on the host; the host load average is recorded per target and was high (11 to 26 at the start of a target), so absolute latencies are inflated and only the relative numbers matter. VictoriaLogs and Loki restart counts were 0 before and 0 after every run.
After the rebase (checked on
3ee88f11, repeated for the changelog and conformance gates onfc506876):go build,go vet ./...,go vet -tags e2e ./test/e2e-compat/,go run ./cmd/configdoc -check,gofmt -l,check_conformance.pyandcheck_changelog_pr.py --base origin/mainall ok;go test -run 'TestMetadataEdge|TestLabel.*Fresh|Freshness|TestHandleLabel|TestLabelValues|TestNestedVectorAggregation'ok.e2e against Loki (fresh isolated copy of the e2e stack per run, CI group patterns, head
0b3a2244before the rebase)Counts are
--- PASS/--- FAIL/--- SKIPlines, subtests included.The changed
TestCompat_LabelsIncludeStreamWrittenAfterCachingpasses on both (11.9 s, it asks again past the 10 s bound). The rebase onto3ee88f11adds only #746's nested-aggregation code to this branch; the e2e groups were not re-run on the rebased head.Metadata-probe load (
mpl_abba.py: main A, PR, Loki, PR, main B)One fresh stack (Loki and VictoriaLogs v1.52.0 compose services, 7 h of generator data), 32 heavy clients looping over the range-metric shapes at 6 h for 180 s per target, a probe of
/labels(no window, 1 h, 6 h),/label/app/valuesand/seriesrotating once a second, then 30 s idle. main is3ee88f11; both builds run their own defaults for-metadata-default-lookback(12h). Cells are p95 / max / first probe in ms; the first probe is the first request after the proxy started.labelslabels_1hlabels_6hlabel_valuesseriesmetadata_edge_answer(the counter of this PR) at the end of each PR target's load phase: PR A 120 exact, 12 stale, 4 waited; PR B 104 exact, 21 stale, 7 waited.metadata_edge_staleness: every stale answer was between 5 and 10 s old (PR A: 8 labels, 4 label values, mean 6.4 s and 5.2 s; PR B: 16 and 5, mean 5.8 s and 5.5 s; none above the 10 s bound).metadata_edge_refresh: 132 and 125 ok, 0 errors.Reading it:
/labelsand label values under load: PR p95 82 to 236 ms against main's 162 to 365 ms; the PR's p95 sits at the 100 ms budget plus scheduling on this host. Max on the PR is 102 to 272 ms on the labels routes. One label-values probe in PR A took 1.73 s: its first request after start, with no answer yet to serve stale./seriesis not covered by this change (PR 183 and 385 ms against main 397 and 148 ms)./labelswith no window): no answer exists yet to serve.Combined with the default-lookback PR (scratch merge, not committed)
A throwaway worktree merging the default-lookback head and this head (both on
3ee88f11; the merge was rebuilt on the final heads and still builds and vets), with thewarmLabelWindowshunk resolved as described above, built and run as the PR target with-labels-cache-warm-tenants=0:labelslabels_1hlabels_6hlabel_valuesseriesmetadata_edge_answer: PR A 120 exact, 17 stale, 2 waited; PR B 119 exact, 13 stale, 5 waited; every stale answer at most 10 s old (one under 5 s).With both changes the label routes stay at the budget under load: p95 102 to 111 ms and max 103 to 128 ms on
/labels(no window, 1 h, 6 h) and label values; the first/labelsafter a fresh start is 7 to 8 ms (warm-up as tenant0plus its read record) where main takes 2.5 and 3.3 s, and the first 6 h/labels102 and 107 ms. The first label-values probe is not warmed (335 and 1084 ms, main 247 and 469 ms), and/seriesis not covered (p95 139 and 329 ms, main 257 and 312 ms). Heavy throughput 846 and 856 requests against main's 745 and 774.Visual (label browser and Drilldown labels; main, PR and Loki as three Grafana datasources)
bench/visual/ci_run.py --base origin/mainwith the label-endpoint page list (Explore label browser and log context, Drilldown labels and a label's values at 15 m, 1 h and 6 h, plus the core pages at 1 h), one isolated stack (VictoriaLogs 7 h, Loki 1.5 h of the same generator data), mainfc506876, PR6d8b89c9(same code as the rebased head). 17 captures, 415 s._extractednaming, sampled detected_labels cardinality, configuration probes) and are the same on main. 6 h has no Loki reference (Loki holds 1.5 h).vis-lbl/montage/*.png(17 files, 1.1 MB),vis-lbl/compare.md,vis-lbl/pixeldiff.json.Pending before ready
Open questions
/seriesfollow-up: a response cache and inventory treatment, so the same bound can apply.