Repository navigation
fix: sum by (detected_level) over a JSON pipeline groups the level the way Loki's ingest does - #760
Conversation
🟢 Performance A/B: faster, no regression139 shape×range — 2 🟢 faster · 137 ⚪ same · results vs Loki: 119 same, 0 new difference(s), 20 pre-existing
¹ re-measured with 7 runs, on windows the first pass did not use, after it moved beyond noise. 137 unchanged shape×range (within noise)
Cold (first-run) timings — what a user opening a panel sees
Why these shapes
base |
PR Quality ReportCompared against base branch Coverage and tests
Compatibility
Performance smokeLower CPU cost (
State
|
✅ Visual smoke: passedBase Fix proofCaptures of the exact cases this pull request adds or fixes (registry case, base | PR | Loki). The verdict compares the PR with Loki where the base did not match. The gate fails a case unless one capture is fixed or improved, or, beyond the Loki data window, the base failed where Loki and the PR both answered with data (the label does not excuse it; only
Regression check
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: |
…e way Loki's ingest does The row evaluator took the stream's level spelling as stored and never read a level key that only the JSON body holds. It now normalizes the stream's level and adds level to its parser hints for a detected_level grouping, as the stats pushdown already did. Only the level stream label and a body level key are read; Loki's other level fields and its ingest keyword scan are not.
…SON pipeline Adds the json-detected-level shape set (a Drilldown logs-volume shape, an __error__ filter shape and a plain | json shape) and the saved A/B results against origin/main on VictoriaLogs v1.52.0: the set at 1h with Loki and at 6h and 24h, plus the control set at 1h. Regenerates the performance evidence and gaps reports.
…ion on every route The row evaluator now gives each row the detected_level the log lines carry (deriveRowLevel) before any stage runs: a level key that is not a known string spelling falls to Loki's keyword scan instead of becoming its own series, the first level key in document order wins, a detected_level stream label keeps its stored value and a body detected_level key is renamed detected_level_extracted. The stats pushdown computes the level in VictoriaLogs with the pipes of the native metric route, placed before the unpack of any other label, and probes the window for the lines those pipes read differently from Loki (a detected_level stream label, two level keys, a level key unpack_json yields no value for); one such line sends the query to the raw-row evaluator.
…d stops tripping on text A filter on detected_level over a JSON pipeline (`| json | detected_level="info"`, Logs Drilldown's detected_level breakdown) now compares the derived level in the raw-row evaluator and in the stats pushdown, which applies it after the pipes that compute the level; `!= ""` always holds. The guard probe for two level keys reads quoted keys in a line that starts with a brace and logfmt keys otherwise, so a message mentioning `level=debug` or `level: high` no longer sends the query to the raw-row evaluator. The plain and logfmt volume tests assert the level of a body, as Loki's ingest reads it.
…xtures, and a known difference is recorded The e2e fixture named level a VictoriaLogs stream field for every app, so a metadata level was stored as a stream label. Each app now names only the stream labels its lines carry. A stream severity with metadata level is read in the pipes' list order by the stats pushdown and stream first by Loki and the raw-row evaluator; the probe asserts the raw-row answer and the case is registered as an open difference of the native pipes.
… JSON line is never read as logfmt VictoriaLogs writes severity_text (v1.50+, with severity_number) or severity (older, no number) for an OTLP record without a severity: Unspecified for 0, Info2 for 10. Loki stores neither, so it reads the number, or the line when the record has none. The pipes took the derived text as the level (Unspecified, Info2), a series Loki never has. They now skip a text derived from the number, and a scratch field marks the rows a stored level decides once, so the unpack pipes test it instead of repeating the stored-field filter (the chain is about 2 KB shorter, under VictoriaLogs' 16 KiB query limit with a service_name selector). A line Loki reads as JSON (a brace first and last) never goes to its logfmt parser, so the pipes no longer unpack it as logfmt: a JSON message holding level=debug as text stays error. The guard probe now also hands the raw-row evaluator a line that only starts with a brace (logfmt for Loki) and a level value with an escape (Loki reads raw bytes); the probe for escapes in keys is gone, Loki decodes them like VictoriaLogs. Probes: OTLP records of both VictoriaLogs storage shapes in the unit and e2e tables, the JSON-line, brace-logfmt, two-spelling logfmt and escape lines, and the two logfmt lines no guard sees (asserted on the raw-row evaluator).
… and what the chain costs The registry rows and the changelog entry describe OTLP severity, the JSON-line rule and the escape guard, record the logfmt and unpacked-row differences no guard sees, count the probe lines, and state the guard's cost as work (a limit 1 bounds the output, not the scan) and the chain's cost as measured.
…s at 8 and at 2 CPUs Replaces the results of the previous revision. The 1h and control runs use the branch's code with all 8 CPUs; Explore's JSON volume and the volume behind a detected_level filter, which the CI perf smoke flagged, are also measured with VictoriaLogs capped at 2 CPUs, where they take 144 ms (main 59 ms) and 794 ms (main 176 ms). The 6h and 24h run seeds VictoriaLogs only.
…nd the fake counts with its own copies of the probe's tables
…efore the stats slot, and the probe tests use the cache clock
…the request is sent
… the witness are described as they behave
…nt orders, on data with and without a stored level, and the cost they show
…hat hold a keyword The regexp that finds Loki's keyword ran over every row left without a level after the key reads. It now runs behind a filter on the nine words as whole case-insensitive words of VictoriaLogs' tokenizer (i()), which the block's token index answers. The filter is a superset of the regexp's matches, never a second decision: every byte Loki accepts around a keyword is a token separator and the folding of (?i) maps no non-ASCII rune onto the letters of the words, so the regexp still decides which rows are matched and what they read. On one hour of rows with no stored level (VictoriaLogs at 2 CPUs) the scan took about 90 ms of the 295 ms of the chain.
…string filter The check for an escape sequence (a backslash followed by u) in the lines no stored level decides ran as a regular expression over every such row, in the probe and in the witness of every pruned request. A substring filter selects the same lines (checked against VictoriaLogs v1.47.0 and v1.52.0) without the regexp engine.
…m and for detected_level The plan unpacked its labels (level, ...) with its own unpack_json and the detected_level pipes unpacked the level keys with another, so every line of a window without a stored level was parsed twice. The pipes now unpack the plan's labels with their level keys in one unpack_json (result_prefix "__j_") and, before the closing delete, copy each label from its prefixed field where the field is not stored, which is what the plan's own unpack with keep_original_fields wrote. The level keys are still read only from rows without a stored level, whatever rows the unpack parsed, and the presence mask never drops a label of the plan. The unpack parses a row only where a label is missing as a stored field or the pipes read the line; the plan's own parsed every row. The chain that holds the labels is found, narrowed and witnessed like any other.
…up of the e2e suite
…try and the registry row
…h measurement orders, on data with and without a stored level, and VictoriaLogs alone at 1h
… rows it proves, and the cold probe that is new
36e6dc8 to
acef15d
Compare
…n and this branch started fresh before each request
…per probes (#764) * perf: the two-keys patterns of the level keys probe run behind a gate of phrases The keys probe ran two regexps that scan the rest of the line after a level key over every line of a window that holds one, which is every line of a body-only window: 320 CPU-ms of 1h of rows, the heaviest probe of the first view of a window. Only a line holding two level keys can match them, so they now run behind a filter that passes the lines in which one key name occurs twice (a sequence of the phrase after itself) or two of the names occur, answered from VictoriaLogs' token index: 50 CPU-ms. The gate is a superset of the patterns, never a second decision; the probe's verdict is the patterns'. * fix: a selector too long for the gated keys probe gets the probe without the gate The gate adds 2.5 KB to the keys probe, so a selector of 11.8 KB to 14.3 KB, which fit VictoriaLogs' 16 KiB query length before, would have had its probe refused. The gate only narrows what the patterns run on, so the text without it gives the same verdict. * perf: the probes of the labels run once for the stored-level query and the chain A plan that groups by a label and reads detected_level asks twice on rows with no stored level, and the verdict of its label probes (main's partial-parse probe among them) was remembered under a key that told the two asks apart, so the same query ran twice in a first view. The label probes and the level probes are remembered apart now: the chain takes the verdict of the label probes from the stored-level query and asks only for the level probes. The verdict is risky if either is. * test: the e2e of the keys gate writes to VictoriaLogs only Its probes read nothing else, and the shared helper pushes the lines to Loki and flushes it, which other tests of the suite do not expect of a test that runs before them. * test: A/B results of the first-view cuts against main and against main before #760, in both measurement orders * docs: changelog entry and registry row for the first-view cuts * test: visual proof pages for the detected_level volumes, and a 5m range * perf: the gate leaves out the pair of a dotted key name and its last word The one occurrence of log.level holds the word level, so the pair of level and log.level admitted every line with that single key and the two-keys regexps ran over it. A line with both keys holds the word twice and passes the sequence of level after level; the gate stays a superset of the patterns. * fix: the keys probe is asked again without its gate when VictoriaLogs refuses the longer text An operator may have lowered -search.maxQueryLen below the gated probe, which is 2.5 KB longer than the probe was. VictoriaLogs' 400 for a query that is too long is told apart from other refusals, and the probe goes out once more without the gate, the same verdict. The edge of the 16 KiB default is pinned with bases of exactly the longest that fits and one byte more. * test: the remembered risk verdicts are scoped to the base and to the filters A window found clean for one base, or for one set of filters that reject unparsed lines, must not clear another base or set in the same tenant and window that holds a risky line: it goes to the raw-row evaluator with the answer it gets asked alone. Both scopes were unpinned: a key without the base, or without the filters, passed every test. * test: a script that measures the first view of a window, the builds started fresh before each request * test: the first-view script records its command without the output directory * test: the first view of a window, every sample: main before #760, main and this branch started fresh before each request * docs: the changelog entry and the registry row cite the first-view samples and say what the probes do on a refusal --------- Co-authored-by: szibis <szibis@users.noreply.github.com>





Summary
sum by (detected_level) (...)over a| jsonpipeline now follows the levelLoki's ingest gave each line on every route that answers the shape, and a
filter on detected_level compares that value. A few lines stay different and are
registered (see "Not done").
Cost: a window whose rows all carry a stored level (a level stream label or
structured metadata, as Loki pipelines send it) is answered from VictoriaLogs
stats grouped by the stored fields, which is main's query: no chain, no level
guard probe, no probe beyond the ones main ran. Explore's JSON volume and the volume behind a
detected_levelfilter, which the CI perf smoke flagged (+52% and +186% on theprevious revision), stay within the harness's noise of main (see the A/B). A
window with a row that has no stored level, or a stored
detected_level, asksagain with the chain, built from the fields and keys the window holds. That
path is still slower than main on the shapes whose answer main gets wrong, by
less than before (Explore's JSON volume on rows with no stored level,
VictoriaLogs alone, 15 runs in each measurement order: 84 ms to 105 ms and
87 ms to 102 ms at 1h; 0.54 s to 0.69 s at 6h and 2.39 s to 2.75 s at 24h; the
previous revision took 38 ms to 282 ms, 0.55 s to 1.5 s and 2.3 s to 6.1 s):
the chain parses each line once, for the plan's labels and for the level, and
scans a line for a keyword only when it holds one. The first view of a window
(nothing remembered) still runs the stored-level query, the level probes and
the presence probe before the chain: about 0.5 s at 1h where main takes 0.08 s.
The numbers and both measurement orders are in the A/B and "Not done".
Loki sets detected_level once per line (
pkg/distributor/field_detection.go):a level stream label or structured metadata first; otherwise, for a line that
starts with
{and ends with}, the first string value of an allowed levelkey (
level,LEVEL,Level,log.level,severity,lvl, ...) at depth 0or 1 in document order, counted only when it is a known spelling; anything
else (a number,
notice, no key, a line that is not JSON) goes to a keywordscan of the whole line, and only a scan that finds nothing is
unknown. Thevalue is structured metadata present on every line, so a body
detected_levelkey is
detected_level_extracted, and adetected_levelstream label keeps itsstored spelling.
The row evaluator (plain
| json,__error__!="", every pushdown fallback)and the stats pushdown (
| json | drop __error__, label filters) read only alevelstream label or body key and normalized it, so on plain| json:{"level":30,"msg":"hi"}was30(Loki:unknown), a pino error line(
{"level":50,...,"err":{...}}) was50(Loki:error),{"level":true}was
true,{"level":"notice"}wasnotice,{"level":"notice","msg":"error connecting"}wasnotice(Loki:error) and{"level":" info"}wasinfo.severity,Level,LEVELand nestedlog.levelkeys and a linewithout a level key that mentions
errorwereunknown. Adetected_levelstream label was normalized, and a body
detected_levelkey replaced thederived value.
Which clients send these shapes: Explore's logs volume (
sum by (level, detected_level) (... | json | drop __error__ [$__auto])) and user-writtenmetrics. Logs Drilldown's volume over
| jsonis answered by the row evaluator;its detected_level breakdown (
sum by (detected_level) (... | json | drop __error__, __error_details__ | detected_level != "" [$__auto])) has the shape ofits native field-breakdown histogram, but the label translator maps
detected_level to level, so that route is never exact for it
(
orderedJSONNativeGroupingIsExact) and it was answered by the row evaluatortoo. It is now served by the guarded stats pushdown (see the A/B: 2.4 s and 502
at 6h/24h before, 0.02-0.30 s now). The plain-selector detected_level volume
that Drilldown sends is the native route, which this change does not touch (see
"Not done").
Loki source
pkg/distributor/field_detection.go(v3.7.7):extractLogLevelFromLogLine,getLevelUsingJSONParser(depth< 2, document order, string values only),detectLevelFromLogLine(keyword scan with word boundaries),normalizeLogLevel;pkg/distributor/labels.go(a colliding structuredmetadata
detected_levelbecomesdetected_level_extracted).Code
internal/proxy/ordered_json_metric.go): a plan that groupsby, keeps (
without) or filters on detected_level (derivesLevel) giveseach row Loki's structured metadata before any stage runs
(
withDerivedLevel), using the derivation the log lines use(
deriveRowLevel, throughlogRowLevels.stringRow). Bodydetected_levelkeys are renamed
detected_level_extractedby the existing collision rule; astream label
detected_levelis kept as stored and the derived level is putunder
detected_level_extracted(detectedLevelName). Thelevelparserhint and the normalization of the previous revision of this PR are gone
(
lokiNormalizedLeveldeleted): one derivation for log lines, metric rowsand the pushdown fallback.
orderedJSONStatsBucketswithstoredLevel): a plan reading detected_level first copies the storeddetected_levelandlevelfields before any unpack (| copy detected_level as __dl_d, level as __dl_l) and groups the buckets by the copies. Eachbucket's level is
translator.NormalizeStoredLevelof the first non-empty ofthe two (a known spelling in any case becomes its level, any other word
stays), which is the chain's spelling pipes in Go, tested against their
regexps and against a table of Loki v3.7.7's
normalizeLogLevelanswerswritten out from its source. The proxy reads a stored
detected_level, thenlevel, and a bucket with a level needs no other field of its list. Lokitakes any allowed stream label before any structured metadata, so a stream
severitywith metadataleveliserrorin Loki andinfohere: arecorded difference (
semantics/detected-level-pipes-known-differences), nota property of this check. A bucket without a stored level, or with a stored
detected_level(a stream label keeps its stored spelling, metadata isnormalised, and the stats cannot tell them apart), returns
errLevelNotStoredand the query is asked again with the chain; the verdictis remembered for the base for five minutes (
levelNeedsChain) so the nextask goes there at once. The attempt runs only the label probes main ran, none
of the level guard probes (they exist for lines only the chain reads).
A filter on detected_level runs in VictoriaLogs on the stored spellings
(
translator.BuildStoredLevelCopyFilter: the spellings of every level thefilter accepts, a word Loki does not know compared as stored, and every row
the stored fields do not decide kept, so that it reaches the chain) and again
in Go on the normalised level (
storedLevelSeries). The series limit(
-max-stats-query-series) applies to the answer's series: the spellings ofone level are VictoriaLogs groups but one series (
INFO,infoandInformationare one, as in Loki), so the groups are counted after the merge(
mergeGroups). The read of the groups is bounded only as a memory guard,twice the limit (
splitGroupSlack): past it the attempt returnserrStatsGroupGuard, the verdict for that query is remembered, and the chainroute, whose groups are its series, counts them and answers Loki's 400 where
it is due. Before this, 300 pods with three levels each under a limit of 500
answered 400 for
sum by (pod) (... | json | detected_level="error"), whereLoki answers 300 series.
translator.BuildDetectedLevelChain(..., DetectedLevelChainGrouping), thepipes the native metric route uses, placed after the prefilters and before
the unpack of any other label (
orderedJSONUnpackPipesAfter), so a bodylevelnever looks stored. A filter on detected_level is applied afterthem (
!= ""always holds and is dropped). Three guard probes join thepushdown's own and share their window cache:
detectedLevelStreamRisk(adetected_levelstream label),detectedLevelKeysRisk(two level keys in aline, which the pipes read in a fixed order; a level value with an escape,
which Loki reads as raw bytes; a line that starts with a brace but does not
end with one, which Loki reads as logfmt and the pipes do not unpack) and
detectedLevelUnpackRisk(a level keyunpack_jsonyields no value for:nested other than
log.level, leading whitespace, text after the closingbrace, a syntax error). One such line in the window sends the query to the
raw-row evaluator. With
-detected-level-body-scan=falsethe raw-rowevaluator answers.
a line that is JSON for Loki (a brace first and last) is never unpacked as
logfmt (
{"msg":"error: cannot set level=debug now"}iserror, notdebug); the severity VictoriaLogs derives for an OTLP record without one(
severity_textUnspecifiedwithseverity_number0, orInfo2with 10,from v1.50; one
severityfield with no number before) is no level field, sothe number decides and a record without a severity falls to the line, as in
Loki. A scratch field
__dl_hmarks the rows a stored level decides once, sothe unpack pipes test it instead of repeating the stored-field filter.
pushdown serves Explore's logs volume at 24h in 0.28 s (DLV4) where the
raw-row evaluator answers 502 (row limit) at 6h and 24h on the same data
(DLV6 below). The pushdown gives Loki's value for every probe line the guard
clears; the lines it cannot see are registered in
semantics/detected-level-pipes-known-differences(see "Not done").translator.BuildDetectedLevelChainwith aDetectedLevelPresence,internal/proxy/detected_level_presence.go): eachpipe passes every block, so the chain is built from what the window holds. One
stats query (
levelPresenceQuery) over the stats query's own base and windowcounts every stored level field and the words of every body key, and the
chain keeps those. It may only over-report: a body key counts as present
when its words occur in the line of a row no definite stored level field
decides (the chain unpacks no other), an escape sequence (
\u) in such aline makes every key present (unpack_json decodes
\u006cevel, which the wordtest cannot see; Loki decodes it too),
severity_numberandseveritykeepthe OTLP pipes (v1.50+ and before), a probe error or an unexpected row keeps
the full chain. The rewrite happens in
vlPostHTTP(pruneLevelChain) forevery
stats_query_rangerequest carrying the chain, so the native metricroute (the translator and its query cache are unchanged) and the pushdown
share it; a request holding the chain twice, and an instant query, keep the
full chain. A window with one stored level field and no body key sends a
chain of 1.5 KB where the full one is 7.1 KB. The probe runs before the
request takes its
stats_query_rangeslot (pruneBeforeSlot), not whileholding one. The mask can be older than the data (a line that arrives late
for a timestamp inside the remembered part), so the narrowed query is also a
witness: pipes before the chain flag every row that holds a stored field or
body key the mask left out, with the probe's own predicates
(
levelPresencePredicate), as a group-by field (__lw) thatlevelWitnessResponsereads back and strips; a flagged row, or an answer toolarge to check, drops the mask and sends the request again with the full
chain, which is exact. A filter on detected_level after the chain passes
flagged rows, so the flag reaches the stats.
claim is that the answer of every row is the answer of the pipes before):
translator.LevelKeywordGate). The keyword regexp, which isLoki's scan (
field_detection.godetectLevelFromLogLine: the first oftrace, debug, fatal, critical, error, err, warning, warn, info by position,
between a left boundary of space, tab, newline,
[,(,{,",=and aright boundary of those and
],),},:,,,!, case folded), ran overevery row left without a level after the key reads. It now runs behind
_msg:(i(trace) OR ... OR i(info)), VictoriaLogs' case-insensitive word filter.The gate is a superset of the regexp, never a second decision: every byte
Loki accepts around a keyword is a token separator of VictoriaLogs'
tokenizer, and the folding of
(?i)maps no non-ASCII rune onto theletters of the nine words, so a matched text is an ASCII word between
separators, which
i()finds. A line the gate lets through and Loki'sboundaries reject (
foo-error,error.) is rejected by the regexp asbefore. The ASCII-only fold of the regexp, and so
İNFO, stay what theywere (registered).
translator.BuildDetectedLevelChainShared,sharedLevelUnpack). A JSON plan that groups by labels (levelforExplore's volume) unpacked them with its own
unpack_json fields (...) keep_original_fields, and the chain unpacked the level keys again withanother. The chain's unpack now reads the level keys and the plan's labels
together (
result_prefix "__j_"), and before the closing delete eachlabel is copied from its prefixed field where the field is not stored,
which is what the plan's unpack wrote. The level keys are read only for
rows no stored level decides (a stored
severity,lvlorseverity_numberdecides a row but is nolevel, so the row'slevellabel still comes from the body), the presence mask never drops a label of
the plan, and the unpack parses a row only where a label is missing as a
stored field or the chain reads the line (the plan's parsed every row).
Only a JSON plan whose labels are plain names, with no
name_extractedlabel, shares;
pruneLevelChainfinds the chain that holds the labelsthrough the request's context and narrows and witnesses it as any other.
followed by
uin the lines no stored level decides (an escaped keyunpack_jsondecodes and the word test cannot see) with a substringfilter,
_msg:*"\\u"*, where they ran a regexp over every such row. Itselects the same lines.
Not done, because the measurement made them moot on this data: a single
format ifcascade for the keyword scan (the gated regexp costs 48 CPU-msof the chain's 269) and a one-key shortcut when the probe shows one body key
(the presence-pruned chain of this window already unpacks only
level, so thereis nothing for it to cut).
coveredWindowProbe, shared with the guard probes'verdicts, whose logic moved there): a verdict covers only the part of a
window older than five minutes (
statsPushdownRiskSettle), the younger part isprobed on every request, so a key that first appears in recent lines is seen
at once; the key now carries the request scope fingerprint (tenant, routing
and forwarded identity), which the guards' key did not; and extending an
entry no longer renews the expiry of the part checked earlier (it did, so a
dashboard that refreshed kept a verdict for ever and a line arriving late
inside it was never seen). Behaviour change for the guards too: a refreshing
dashboard checks the last five minutes on every refresh and the whole window
again every five minutes.
VictoriaLogs queries over the whole window when it is not remembered, and on
every request over the part of the window younger than five minutes. Each stops at its first matching line, which bounds its output, not
its work: on a clean window each scans the lines that hold a level-key word
and the rows without a stored level. The chain adds work on every row of the
window (about 70 pipes unpruned, 18 for a window with one stored level field; most
are skipped for a row with a stored level, but each pipe still passes every
block; the witness is a third of what is left, see the A/B). The guard is a superset: one line it
cannot clear sends the whole query to the raw-row evaluator, exact but
bounded by the row limit, so on a long range it answers 502 where the
pushdown answered 200. Ordinary data can trip it: a body with both
leveland
severity(audit logs), or a stream labeldetected_level. A messagethat merely mentions
level=debugorlevel: highdoes not.| logfmtand plain-selector logs volume plans (sum by (level, detected_level)) take the same pipes. That changes their answer: a streamwithout a level label now gets the level of its body (a logfmt
level=warnkey, a JSON key or a keyword), as Loki's ingest reads it, where main said
unknown. The logfmt plan has the guard; the plain-selector plan has noraw-row fallback and runs without it (see "Not done").
Tests
Unit
TestOrderedJSONDetectedLevelLikeLoki: 55 probe lines (pino numericlevels,
notice, a padded level,severity,Level,LEVELand nestedlog.levelkeys, two level keys in both orders, a level key mentioned insidea string, stream
level/severity/detected_level, storedlevel,severityanddetected_levelfields, malformed lines with a bodydetected_levelkey, a JSON message holding logfmt text, a line that onlystarts with a brace, two logfmt spellings of
level, escaped level valuesand keys, and twelve OTLP records of both VictoriaLogs storage shapes:
severity_textwithseverity_numberfrom v1.50, oneseverityfieldbefore), each through the row evaluator (
| json,__error__="") and thepushdown (
| json | drop __error__), whose fake evaluates the chain with a Goemulation of the pipes (
emulateDetectedLevelChain), so the test shows wherethe chain would differ from Loki and asserts the guard hands exactly those
lines to the raw evaluator (
rawRows). The emulation follows the chain'stext, which
TestBuildDetectedLevelChainpins; the pipes themselves run onlyin the e2e tests.
TestOrderedJSONDetectedLevelKnownDifferencesasserts theraw-row evaluator reads two logfmt lines like Loki (
LvL=warn, a syntax errorbefore the level key) and the pushdown keeps the pipes' value.
TestOrderedJSONDetectedLevelMixedRowsmixes the lines in one window forcount and bytes.
TestOrderedJSONDetectedLevelFiltersruns filters ondetected_level (
!= "",=,=~,!=, without the error drop, with__error__=""), also as a Logs Drilldown request, over all probes and over thelines the pipes read like Loki, asserting the guarded pushdown answers the
latter with the filter applied after the pipes.
Presence and stored-level tests (
detected_level_presence_test.go, and theprobe table run twice, with the full and with the pruned chain, every probe
line asked of a fake that answers the presence probe from its rows):
TestDetectedLevelPresenceKeepsAKeyOfOneLateLine(a key on one late line ofthe window is read),
TestDetectedLevelPresenceProbeFailureKeepsFullChain(backend error, no counts, a short row),
TestDetectedLevelPresenceNeverTrustsRecentAbsence(a key first seen in recent lines is read on the next request),
TestCoveredWindowProbeKeepsTheAgeOfTheCheck,...RefreshChecksOnlyTheRecentTail,...KeepsScopesApart,TestPruneLevelChainLeavesTwoChainsAlone,TestLevelPresenceQuery/FromMask,TestDetectedLevelPresenceNativeRoute,TestStoredLevelDecidesDetectedLevel(nine spellings through the json,logfmt and plain plans and two filters on detected_level, one stats query,
no chain, no level guard, no presence probe),
TestStoredLevelAttemptFallsBackToChain(one row without a level; thesecond ask goes to the chain at once),
TestNormalizeStoredLevelMatchesTheChain,TestBuildDetectedLevelChainPruned(the OTLP shapes included). The probe tablegained
escaped level key, long spelling({"\u006cevel":"Information"}:infoin Loki v3.7.7, which decodes keys; the keyword scan cannot find it, soonly the decoded key gives the answer) and
stream detected_level wins over a stream level, in the unit table and the e2e table.Mutations (each makes the named tests fail; tests / subtests that failed):
the presence probe reporting every field absent 6 / 19 (the probe table in
the pruned arm, the late-line, native-route and filter tests); body-key
flags ignored 4 / 1; a probe error answered with an empty presence 4 / 22;
the settle clamp removed 1 (a recent absence is trusted); the expiry renewed on
extension 1; the escape flag ignored 2 / 1; the number pipes pruned away when
only
severityis present (VictoriaLogs before v1.50) 1 in the translatortest and 1 / 2 in the OTLP lines of the probe table; the scope dropped from
the key 1; two chains pruned with the first base 1; the stored-level
normalisation made case-sensitive 3 / 7; a bucket without a level accepted 7 /
104; a stored detected_level accepted 1 / 2; the verdict not remembered 1; the
filter on detected_level ignored 2 / 3; the stored-level attempt disabled 5 / 13.
Translator unit tests pin the chain (
TestBuildDetectedLevelChain: thesynthesised-severity skip, the
__dl_hmarker, the logfmt condition),BuildHasLevelFilterfor both OTLP shapes and the stored-level filter forthe derived
severitynames.Fail without the fix: with the guard's
Level=info LEVEL=errorclause removedthe probe
logfmt level keys of two spellingsfails; with the escaped-valueclause removed
escaped level valuefails; with the brace-without-closingclause removed
logfmt after a bracefails. In the e2e test, with the pipesreading a derived OTLP severity as a level, six subtests fail on each
VictoriaLogs version (
OTLP without severity,OTLP without severity, error word,OTLP fine severity numberand the three OTLP filter groups). Theearlier revision's own mutations still hold (against
10b0941fthe first 28probes failed on 55 of 84 subtests; chain not inserted - 29; guard probes
off - 17).
The existing pushdown tests changed only in their expectations of the query
(the chain, three more probes), of the unpack fields (
by (detected_level)no longer unpacks
level) and of a filter on detected_level (now pushed).Their Loki-reference harness (
lokiLevelVolumeReference) is a hand-builtmodel of Loki's answer for simple fixtures, not Loki's: it normalizes the
spelling and falls to the keyword scan as Loki's ingest does; the comparison
with real Loki is the e2e tests. The plain logs-volume test asserts the level
of a logfmt body.
e2e
TestRangeMetricCompatibilityJSONDetectedLevelProbesagainst real Loki:50 lines (the malformed ones valid only under
drop __error__; seven areOTLP records pushed to Loki and to VictoriaLogs' OTLP endpoint), one stream
each,
| jsonand| json | drop __error__, the container proxy and anin-process proxy; it asserts Loki's own answer equals the table and that the
pushdown serves the lines the pipes read like Loki and hands the others to the
raw-row evaluator. Ten more subtests run filters on detected_level and Logs
Drilldown's detected_level breakdown (with its
X-Query-Tagsheader) againstLoki, three of them over the OTLP records, and assert the breakdown is one
guarded stats request without raw rows on clean lines. Loki v3.7.7 agreed
with the table on every line, including the escaped value (
unknown), theescaped key (
warn),LvL=warn(warn) and the unterminated logfmt line(
error), measured separately.TestRangeMetricCompatibilityJSONLogsVolumegained a plain stream line whosebody holds
level=warn.ingestJSONVolumeFixturetakes extra stream labels(
labels) and names the VictoriaLogs stream fields per app from the labelsits lines carry, so structured metadata (a stored
level) is not made astream field.
Unit
TestStoredLevelPlanCountsTheSeriesOfTheAnswer(the nine-spellingfixture of
TestStoredLevelDecidesDetectedLevelunder-max-stats-query-series3 to 6): a filter on one level keeps its spellings only (three series at a
limit of three, where the plan answered 400 for the nine groups), a regexp, a
negated and an unknown-word filter, the merged answer exactly at the limit
(200), one over it (400 with Loki's message), and a read past the group guard
that the chain answers.
TestStoredLevelPlanManyPodsUnderTheSeriesLimit(30pods of three levels under a limit of 50 and of 40: 200 with 30 series, and
the verdict of the guard remembered),
TestStoredLevelCopyFilterIsExact(thefilter pipes against
NormalizeStoredLevelfor 20 filters and 25 storedwords, and rows the stored fields do not decide are kept).
TestNormalizeStoredLevelIsLokisNormalizeLogLevelis a table of Lokiv3.7.7's
normalizeLogLevelanswers written out from its source, andTestStoredLevelDecidesDetectedLevelstates its expectations literally(they no longer come from
NormalizeStoredLevel).Unit
TestDetectedLevelWitnessCatchesALateLine(a mask remembered forlevelonly, then a line{"msg":"error retry","severity":"warn"}stampedinside the covered window:
warn, Loki's, where the pruned chain answerederror; on the pushdown and the native route; the mask is probed again afterit),
TestLevelWitnessResponse,TestPrunedChainWithWitnessFitsTheQueryLimit,TestLevelPresenceProbeRunsBeforeTheStatsSlot(no slot is held while theprobe runs),
TestCoveredWindowProbeKeepsTheAgeOfTheCheck(the cache clock,no sleeps) and
TestCache_SizeCountsTheKey.Unit
TestLevelPresenceSweepOnePositionAtATime: each of the 31 positions ofthe presence mask (16 stored fields, 14 body keys, the escape flag) alone in
a window must give exactly its field or key in the pruned chain from one probe
and one chain query; forcing any one position to 0 in the probe fails its
subtest (31 of 31, where the earlier tests caught 10), because the witness
asks again with the full chain and the test counts the queries. The fake
VictoriaLogs counts with its own copies of the probe's tables.
FuzzStoredLevelCopyFilter, 30 s withFuzzTranslateLogQLandFuzzParseDropConditions(no finding).Cheaper chain (the three cuts above; a test per claim, each answer written out
from Loki v3.7.7's source or measured against it, not taken from the code):
TestKeywordScanLikeLoki(94 lines with Loki's literal answers fromdetectLevelFromLogLine: case,errors/terror/warnings/information,several keywords with the smallest position winning,
warning: error,critical erroragainsterror critical, every boundary byte on eachside including
\r, a no-break space,é,ж,€and invalid UTF-8; thechain's scan with the gate and the regexp alone both give them),
TestKeywordGateIsASupersetOfTheRegexp(400,000 generated lines: the regexpmatching implies the gate matching, the gate evaluated from the text
LevelKeywordGate()returns with VictoriaLogs'i()rules written out fromfilter_any_case_phrase.go),FuzzKeywordGateIsASupersetOfTheRegexp(thesame, and the scan against a plain search for the first bounded keyword; 30 s,
no finding),
TestLevelKeywordGateText,TestBuildDetectedLevelChainShared(one
unpack_json, the condition in each case, the level key reads gated by-__dl_h:*, the copies before the delete, the mask never dropping a label),TestSharedLevelUnpackEligibility,TestSharedUnpackKeepsThePlansLabelsLikeLoki(ten lines, the unpruned and the pruned chain: a stored
severity,lvl,severity_number,LevelorLEVELwith a bodylevel, a streamlevel, astored
level; the labels are Loki's, oneunpack_jsonand the witness inthe request sent) and the 30 keyword lines in the probe tables, unit and e2e.
The unit fake of VictoriaLogs runs the unpack and the copies of a shared
chain as VictoriaLogs does and emulates the rest of the chain whole, with the
rows a stored level decides taken from the same stored-field list as the
chain's marker.
e2e (VictoriaLogs alone,
TestRangeMetricCompatibilityDetectedLevelPipeVariants):1,489 generated rows (89 bodies, 26 stored-field sets) per VictoriaLogs
version, the pipes as they were against the pipes as they are (gate only;
gate and shared unpack; full and pruned chain; the plan's unpack with and
without its condition), per row, identical on v1.47.0 and v1.52.0;
TestRangeMetricCompatibilityEscapeSubstringFilter(the regexp and thesubstring filter select the same 7 of 14 lines);
TestRangeMetricCompatibilityJSONDetectedLevelSharedUnpackagainst Loki(11 lines in windows that also hold a line no stored level decides,
sum by (level, detected_level): the same two series as Loki, one chain request withone
unpack_json, no raw rows; OTLP severity numbers included).Mutations (each makes the named tests fail; tests / subtests that failed):
the gate without
err5 tests (+ the e2e variants); no gate 2; the plan nevershares 5 / 27; the shared unpack parsing only the rows the chain reads 2 / 10
(+ 1); the shared unpack without the plan's labels 3 / 5; the labels not
copied 5 / 19; the escape check a regexp again 1; the pruner not knowing the
shared chain 1 / 10; the level key reads not gated by
-__dl_h:*1 (thetranslator text test).
Registry
Visual proof
visual: none: the generator keeps the stream label level equal to the bodylevel and uses one lowercase spelling, so main and the branch render the same
Explore and Drilldown panel (1h A/B: same series and sums as Loki on every
shape). The e2e probes against Loki are the proof.
e2e against real Loki v3.7.7
Isolated compose project
dl5e(a fresh stack per VictoriaLogs version,Grafana started), image built from this branch,
/readyand/healthcheckedbefore any test, VictoriaLogs restart count 0 before and after every run. The
route checks count the stored-level attempt (
isStoredLevelAttempt,levelStatsOutcome) and the presence probe (isLevelPresenceCall).Command:
go test -tags=e2e -count=1 -p 1 -run '^(TestSetup_IngestLogs|TestRangeMetricCompatibility.*|TestDrilldown_LongRangeVolume_.*|TestCompat_HeavyQueryProtection|TestCompat_PatternLineFilter.*|TestCompat_DetectedLevel.*)$' ./test/e2e-compatTestRangeMetricCompatibilityJSONDetectedLevelSeriesLimit,TestRangeMetricCompatibilityJSONDetectedLevelSharedUnpack,TestRangeMetricCompatibilityDetectedLevelPipeVariantsandTestRangeMetricCompatibilityEscapeSubstringFilter(new), andTestRangeMetricCompatibilityJSONDetectedLevelProbes(131 subtests over 80 probe lines, through the stored-level plan or the chain),...JSONDetectedLevel,...JSONFilterPushdown,...JSONLogsVolume,TestDrilldown_LongRangeVolume_*(Grafana),TestCompat_DetectedLevel*(corpus: 552 lines, 552 agree with Loki)TestRangeMetricCompatibilityJSONDetectedLevelSeriesLimitingests 12 pods withthree spellings of
errorand one ofinfoeach into Loki and VictoriaLogs andruns
sum by (pod, detected_level)(24 series) and the same filtered todetected_level="error"(12 series) through an in-process proxy whose-max-stats-query-seriesis the answer's series count, one more and ten timesthat, against the stack's Loki (limit 1000000): the same series, not a 400; and
one below the count: Loki's message. Loki's own boundary was checked on a throwaway Loki v3.7.7 with
max_query_series24 and 23 and the same 12-pod fixture (outside the suite, whose Loki has a limit of 1000000): 24 series under a limit of 24 is a 200, under 23 a 400, and the filtered query (12 series) a 200 under both; Loki's check islen(series) > maxSeries(pkg/logql/engine.go,pkg/querier/queryrange/limits.go), so the series count at the limit passes, as it does here. On the previous revision the limits equal tothe series count and one above it fail (a 400 where Loki answers 200). Each version ran on a fresh stack
(a second run on one stack re-ingests the fixtures and doubles VictoriaLogs'
counts), VictoriaLogs restart count 0 before and after.
A/B against origin/main (VictoriaLogs v1.52.0, capped at 2 CPUs)
Base
1dcb79e0vs branch (the code of this revision), warm p50 after a cold run(5 runs at 1h, 3 at 6h and 24h; a shape the first pass moved is measured again
over 7 runs at 1h or 3 at 6h and 24h on windows it did not use), targets
interleaved per request, same step-aligned windows, one fresh stack per run
(about 290,000 lines per hour of the harness's backfill); VictoriaLogs runs under
docker update --cpus 2like the CI runner (the harness has no flag for it:bench/ab/pr_smoke.pywas wrapped to apply it right afterstack.up), restarts0 -> 0 on every run, noise settings are CI's (30% and 100 ms). Every run was
made twice, with the base build measured first and with the branch build
measured first: the position of a target in the pair moves a cheap shape by 20%
to 70% in either direction (Explore's volume on the data without a stored level:
base first 118 ms and branch second 97 ms, branch first 169 ms and base second 95
ms), and the two columns show it. Loki parity is checked at 1h (6h and 24h
seed VictoriaLogs only). Saved under
bench/ab/results/(
2026-10-14-detlevel-*.json, replacing the previous revision's) and, for thesecond order and the data without a stored level,
bench/ab/results/oneoff/.Runs:
python3 bench/ab/pr_smoke.py --base 1dcb79e0 --ranges 1h --runs 5 --confirm-runs 7 --selection <sel.json> --out <dir> --loki-mem 3g --vl-mem 4g [--no-level-label]. All 16 runs: 0 new differences from Loki, restarts 0 -> 0.Data with a level stream label on every row
A window whose rows all carry a stored level is answered by the stored-level
plan, which none of the cuts touches; the numbers are those of the previous
revision's, measured again. Explore's JSON volume (D) and the volume behind a
level filter before the parser (DL6) stay within the harness's noise of main:
The detected_level shapes (DLV1-DLV6), 1h with Loki and 6h and 24h without:
DLV5 (the stored-level plan reads no body) and DLV6 (Logs Drilldown's breakdown,
the raw-row evaluator on main) are faster; DLV1-DLV3 are the raw-row evaluator,
unchanged. Control set at 1h, both orders (every shape is within noise; Loki
parity is the same as on main,
topk rate by appdiffers on both):Cold windows with a level stream label
Data with no stored level (the level only in the line)
The same backfill seeded with
--no-level-label(the generator leaves the levelout of the stream labels; the lines keep it in the JSON or logfmt body, or have
none). This is the data the chain reads, and where main answers 4 series for D
where Loki answers 8. The previous revision's numbers, for comparison (base ->
branch, base measured first): D 38 -> 282 ms at 1h, 547 ms -> 1.50 s at 6h, 2.29
s -> 6.09 s at 24h; DLV5 56 -> 99 ms, 532 ms -> 897 ms, 2.24 s -> 3.79 s.
Warm, VictoriaLogs alone (no Loki in the loop), 15 runs, 1h, each order:
Warm, with Loki in the loop at 1h (the position in the pair moves D: 118 -> 97
ms with the base first, 95 -> 169 ms with the branch first), and at 6h and 24h
(VictoriaLogs only):
Cold (the first request of a shape in a fresh process: the stored-level attempt,
the level probes, the presence probe and the chain, none of them remembered):
The cold request of D at 1h on the VictoriaLogs side, from a proxy restarted before
each request, three requests (duration of each call): the heaviest guard probe
264-296 ms, the stored-level attempt 64-127 ms, the other guard probes 29-188
ms, the presence probe 71-182 ms, the chain 200-296 ms (it shares the 2 CPUs
with the probes); 470-515 ms in all against 80 ms for main and 550-680 ms for
the previous revision (both builds restarted on one stack). The heaviest probe is
detectedLevelKeysRisk(two level keys in a line, an escape in a level value, abrace without its closing brace: four regexp alternatives over the lines that
hold a level-key word), which this change added; main's cold request runs
its partial-parse probe (55-75 ms) and its stats query only. The probes are the
cold cost, not the chain: the first view of a window pays them once per five
minutes (see "Not done").
The harness's cold value is one sample per run, the first request in a fresh
process, and does not compare between sessions: this revision's table above says
591 ms and 458 ms for D, the previous revision's body said 304 ms and 218 ms. The
comparison to read is the restart measurement on one stack above: previous
revision 550-680 ms, this one 470-515 ms, main 80 ms.
Where the time goes (VictoriaLogs alone, 1h, body-only data)
Cgroup CPU time per query is the measure to read, not the wall time: at 2 CPUs
VictoriaLogs' wall time moves in steps of the 100 ms quota period, and at 6h and
24h the wall time follows the CPU time. Median of 12 runs, the queries the proxy
sends for Explore's volume (D);
without Xleaves one group of pipes out of thechain, so the difference is the cost of X:
DLV5 (no label of the plan): main's 99 ms / 217 CPU-ms, previous chain 190 ms /
344 CPU-ms, this revision's 107 ms / 241-258 CPU-ms.
What is left on the warm path is the witness (a third of the chain's CPU) and
the marker pipe it reads. It evaluates 13 body-key words and 15 stored-field
tests per row; grouping the body-key words under one test of the marker
measured 10 to 20 CPU-ms less and is not done.
Quality gate: High-concurrency throughput
TestLoad_HighConcurrency_MemoryStability(100 goroutines x 1000 requests tohandleLabelsagainst a fake backend, median of 3, measured for the head firstand for the base four minutes later on the same runner) does not touch this
change:
handleLabelsand the cache are unchanged, and the diff touches thedetected_level paths and
vlPostHTTP, where every POST now costs one substringcheck for the chain (a needle longer than the query returns at once). Six alternating local runs of 3 repetitions on the
base and the head binaries (8 CPUs, GOMAXPROCS=4) gave the same distribution:
the per-run medians, which is what the gate compares, were 1.09M-1.18M requests/s
for the base (median 1.146M) and 0.85M-1.18M for the head (median 1.156M); one
head run fell 26% below the others with the same code, as the gate's -27.8%
did. The same workflow passed on the two earlier runs of this branch. It is
runner noise.
Data-to-data match against Loki
Every row above carries "result vs Loki" from the harness: series count equal
and the sum of all points within the shown percentage of Loki's, for base and
branch alike (the harness fails a run whose branch differs from Loki where the
base did not: 0 new differences in every run; one pre-existing,
topk rate by app, which differs on main too).Not done
sum by (detected_level)without a parser) does not use the stored-level plan(its query comes from the translator, which has no window): it keeps the chain,
pruned by the presence probe, unguarded:
{"msg":"x","severity":"error","level":"info"}isinfowhere Loki sayserror, and adetected_levelstream label is normalized. Measured on thesame fixtures; registered open as
semantics/detected-level-pipes-known-differences. The Explore plain-selectorvolume plan has no raw-row fallback either, so it runs the chain without the
guard.
the same row: a stream level field outranked in the pipes' list order by a
metadata one (stream
severity=errorwith metadatalevel=info:errorinLoki and under
| json,infounder| json | drop __error__); a logfmtlevel key in another case (
msg="error x" LvL=warn: Lokiwarn, pipeserror); a logfmt syntax error before the level key(
msg="unterminated error level=info: Lokierror, pipesinfo); a rowVictoriaLogs unpacked from a JSON body with a stored level
(
{"level":"notice","msg":"error later"}: Lokierror, pipesnotice, thesame on main). The raw-row evaluator reads the first three like Loki.
keys gets the raw-row evaluator, and its row limit, on long ranges.
with a row that has no stored level (plain text tenants, OTLP records, a
collector that does not promote the level) pays the chain, which reads every
line, after the stored-level attempt. On the harness's backfill seeded
without the level label (see the A/B), VictoriaLogs alone: Explore's JSON
volume (D) 84 ms -> 105 ms and 87 ms -> 102 ms at 1h (both orders, 15 runs),
0.54 s -> 0.69 s at 6h, 2.39 s -> 2.75 s at 24h; DLV5 88 -> 99 ms at 1h,
2.24 s -> 2.74 s at 24h; main answers 4 series for D there where Loki answers
8. What is left is the witness (87 of 269 CPU-ms), the keyword regexp (48) and
the level keys' parse (20). The first view of a window is the larger gap:
the probes (
detectedLevelKeysRisk, which this change added, alone takes 290 ms),the presence probe and the stored-level attempt run before and beside the chain: 470-515 ms for D at
1h against 80 ms for main (1h cold, harness: 591 ms and 458 ms against 68 ms
and 180 ms; 24h: 6.8 s against 2.7 s), once per five minutes for a window the
proxy remembers. Options, none taken because each is a trade of exactness or
a plan change: fold the presence probe into a guard probe (one scan less);
gate the heaviest guard probe's regexps behind word filters as the keyword scan is
(each needs its own exactness proof); trade the witness for a
shorter memory of the mask (the witness exists so a late line cannot be
misread);
contains_anyinstead of nine word tests (VictoriaLogs v1.52 only,so a capability-gated fallback). The native route pays the chain on every window (warm 12 ms -> 20 ms and
10 ms -> 23 ms in the two orders, the control set's
detected_level volume; ona cache miss 14 ms -> 106 ms, measured on the previous revision).
splitGroupSlackanderrStatsGroupGuardalso exist on branchperf/json-valid-split, which this change does not touch; whichever lands secondreconciles the two.
those of the previous revision plus that): the stored-level plan sends a few hundred bytes of pipes. The
chain path is 4.2 KB for Explore's volume with a
service_nameselector (9.8 KBunpruned) and 8.0 KB with a regexp selector of seven long names (14.4 KB
unpruned; the generator's seven names match no row, so the chain is at its
smallest there: the bound is the full chain, 14.4 KB, and the presence probe
is the base plus 1.4 KB; the largest request is then a guard probe at 9.4 KB;
the witness adds up to 1.5 KB to a pruned request, and a unit test keeps the
witnessed request of a 6 KB selector under the limit), against
VictoriaLogs' 16 KiB
-search.maxQueryLen; a window whose presence cannot betold keeps the full chain and its size, and a longer query answers 502 as any
over-long query does.
older than five minutes can miss a line that arrives later than five minutes
after its timestamp, until the entry expires (five minutes after the check of
its oldest part). The part younger than five minutes is always probed. The
presence mask has no such window: the narrowed query flags a row it would
misread (the witness) and is asked again with the full chain.
stats_query_rangeslot in the stats pushdown (collectRangeMetricHits); theburst-fused Drilldown breakdown (
drilldown_burst_coalescer.go) and thebreakdown handler (
metric_binary.go) take a slot first and probe insideit. A slot cannot deadlock on the probe (the probe takes no slot and holds
no admission token while the request waits), it can only be held for one
probe.
this change; the A/B and e2e above are the proofs.
| detected_level="info"before the parser keeps the translator'srendering, which main uses too (
unpack_logfmt | filter level:="info"in thebase of the stats query): the sum differs from Loki's by 0.2% to 0.4% on base
and branch alike (
sum +-0.19%,+-0.36%above). The Summary's "a filter ondetected_level compares that value" holds for filters after the parser; this
one is not changed here.