This is an automated email from the ASF dual-hosted git repository.
hanahmily pushed a commit to branch main
in repository https://gitbox.apache.org/repos/asf/skywalking-banyandb.git
The following commit(s) were added to refs/heads/main by this push:
new c22f7d423 Fix wrong QL cache missing top-K logs (#1220)
c22f7d423 is described below
commit c22f7d42392b8ef80f180cee61fab999cabc880f
Author: mrproliu <[email protected]>
AuthorDate: Sun Jul 19 08:21:49 2026 +0800
Fix wrong QL cache missing top-K logs (#1220)
* Fix wrong QL cache miss top-K logs
* increase the cache size of prepared ql
---
banyand/liaison/grpc/bydbql.go | 55 +++++++---
banyand/liaison/grpc/bydbql_cache.go | 97 ++++++++++++++---
banyand/liaison/grpc/bydbql_reparse_test.go | 163 ++++++++++++++++++++++++++++
banyand/liaison/grpc/bydbql_test.go | 99 ++++++++++++++---
banyand/liaison/grpc/server.go | 2 +-
docs/operation/configuration.md | 2 +-
6 files changed, 371 insertions(+), 47 deletions(-)
diff --git a/banyand/liaison/grpc/bydbql.go b/banyand/liaison/grpc/bydbql.go
index 97e714ac9..7a6422f2f 100644
--- a/banyand/liaison/grpc/bydbql.go
+++ b/banyand/liaison/grpc/bydbql.go
@@ -74,6 +74,8 @@ func (b *bydbQLService) Query(ctx context.Context, req
*bydbqlv1.QueryRequest) (
// cacheResult tags the access-log entry with the prepared-statement
cache
// outcome so operators can find un-cached queries: entries logged under
// "bydbql-miss" / "bydbql-bypass" are the ones that did not hit the
cache.
+ // A "reparse" is folded into "miss" here — it is a miss to anyone
searching the
+ // access log; only the top-K tracker cares about the distinction.
var cacheResult string
defer func() {
duration := time.Since(start)
@@ -91,7 +93,11 @@ func (b *bydbQLService) Query(ctx context.Context, req
*bydbqlv1.QueryRequest) (
if b.queryAccessLog != nil {
service := "bydbql"
if cacheResult != "" {
- service = "bydbql-" + cacheResult
+ tag := cacheResult
+ if tag == cacheResultReparse {
+ tag = "miss"
+ }
+ service = "bydbql-" + tag
}
if errAccessLog := b.queryAccessLog.WriteQuery(service,
start, duration, req, err); errAccessLog != nil {
b.l.Error().Err(errAccessLog).Msg("bydbql
access log error")
@@ -105,8 +111,12 @@ func (b *bydbQLService) Query(ctx context.Context, req
*bydbqlv1.QueryRequest) (
if err != nil {
return nil, status.Errorf(codes.InvalidArgument, "failed to
parse query: %v", err)
}
- if cacheResult == "miss" {
- b.dumper.observeMiss(req.Query)
+ // Track only re-parses, not first-ever compiles. Every template pays
one unavoidable
+ // cold-start compile; feeding those to the tracker both buries the
real signal and,
+ // once the distinct-template count passes bydbqlTopKSize, inflates
every count through
+ // Space-Saving's inheritance. The cache decides (it alone can), the
caller acts.
+ if cacheResult == cacheResultReparse {
+ b.dumper.observeReparse(req.Query)
}
bound, err := stmt.Bind(req.Params)
if err != nil {
@@ -166,14 +176,18 @@ func (b *bydbQLService) Query(ctx context.Context, req
*bydbqlv1.QueryRequest) (
return resp, nil
}
-// topKDumper tracks the top cache-miss and slow queries and, on a supervised
+// topKDumper tracks the top re-parsed and slow queries and, on a supervised
// goroutine, periodically logs the cumulative top-K. All methods are
nil-safe, so the
// call sites need no guards when the top-K log is disabled (the dumper is
nil).
type topKDumper struct {
- miss *topK
- slow *topK
- l *logger.Logger
- cancel context.CancelFunc
+ // reparse holds only templates the cache had already compiled once and
had to
+ // compile again. First-ever compiles are excluded at the call site,
which is what
+ // keeps this tracker near-empty on a healthy cluster — and therefore
keeps its
+ // counts exact, since Space-Saving only distorts them once it
saturates.
+ reparse *topK
+ slow *topK
+ l *logger.Logger
+ cancel context.CancelFunc
}
// newTopKDumper starts the trackers and the dump goroutine; a non-positive
interval
@@ -183,7 +197,7 @@ func newTopKDumper(interval time.Duration, l
*logger.Logger) *topKDumper {
return nil
}
ctx, cancel := context.WithCancel(context.Background())
- d := &topKDumper{miss: newTopK(bydbqlTopKSize), slow:
newTopK(bydbqlTopKSize), l: l, cancel: cancel}
+ d := &topKDumper{reparse: newTopK(bydbqlTopKSize), slow:
newTopK(bydbqlTopKSize), l: l, cancel: cancel}
run.Go(ctx, "liaison.grpc.bydbql.topk-dump", l, func(ctx
context.Context) {
ticker := time.NewTicker(interval)
defer ticker.Stop()
@@ -199,9 +213,9 @@ func newTopKDumper(interval time.Duration, l
*logger.Logger) *topKDumper {
return d
}
-func (d *topKDumper) observeMiss(query string) {
+func (d *topKDumper) observeReparse(query string) {
if d != nil {
- d.miss.observe(query, 0)
+ d.reparse.observe(query, 0)
}
}
@@ -217,13 +231,20 @@ func (d *topKDumper) close() {
}
}
-// minReparseMisses is the smallest cumulative miss count worth logging. Every
-// parameterized template misses exactly once on its cold-start lookup, so
count==1 is
-// benign; only count>=2 means the template was evicted and re-parsed
(thrashing).
-const minReparseMisses = 2
-
func (d *topKDumper) dump() {
- d.logTopK(d.miss.snapshot(), minReparseMisses, "top bydbql cache-miss
queries", func(s topKSlot) string {
+ // No count threshold, same as the slow dump: the tracker is fed only
re-parses, so
+ // every entry already means the cache compiled a template it had
compiled before.
+ //
+ // A threshold of 2 used to stand here as the ONLY thing separating
thrashing from
+ // cold starts, and it could not do that job. Cold-start misses were
fed to the
+ // tracker, and once the distinct-template count passed bydbqlTopKSize,
Space-Saving's
+ // "new key inherits the evicted minimum's count + 1" ratcheted every
count to N/k.
+ // Measured against SkyWalking OAP (2495 distinct templates, zero
evictions, so every
+ // true count was 1): 2495/128 = 19.5, all 128 slots reported 19-20,
and every one of
+ // them cleared the threshold. Excluding cold starts at the source
fixes that at the
+ // root; keeping the threshold on top of it would only re-hide the real
re-parses the
+ // exclusion just made visible.
+ d.logTopK(d.reparse.snapshot(), 1, "top bydbql cache-miss queries",
func(s topKSlot) string {
return fmt.Sprintf("%q count=%d", s.key, s.count)
})
d.logTopK(d.slow.snapshotByLatency(), 1, "top bydbql slow queries",
func(s topKSlot) string {
diff --git a/banyand/liaison/grpc/bydbql_cache.go
b/banyand/liaison/grpc/bydbql_cache.go
index ba03a96f7..2a9e8b077 100644
--- a/banyand/liaison/grpc/bydbql_cache.go
+++ b/banyand/liaison/grpc/bydbql_cache.go
@@ -20,6 +20,7 @@ package grpc
import (
"sync/atomic"
+ "github.com/cespare/xxhash/v2"
lru "github.com/hashicorp/golang-lru"
"github.com/apache/skywalking-banyandb/pkg/bydbql"
@@ -40,8 +41,12 @@ type cacheValue struct {
// via curBytes and RemoveOldest. All shared state is either behind the LRU's
own
// lock or atomic, so the cache needs no mutex of its own.
type preparedCache struct {
- metrics *metrics
- lru *lru.Cache
+ metrics *metrics
+ lru *lru.Cache
+ // evicted remembers the 64-bit hashes of recently evicted keys, so a
later miss on
+ // one of them can be recognized as a re-parse rather than a first-ever
compile.
+ // Hashes, not the query text: the text is multi-KB, the hash is 8
bytes.
+ evicted *lru.Cache
maxBytes int
curBytes atomic.Int64
hits atomic.Uint64
@@ -57,20 +62,75 @@ func newPreparedCache(size, maxBytes int, m *metrics)
*preparedCache {
if size > 0 {
// onEvict keeps curBytes in step with both the LRU's own
count-based
// evictions and our byte-based RemoveOldest calls; it runs
without the
- // cache lock, so the atomic add is safe.
- if l, err := lru.NewWithEvict(size, func(_, value interface{}) {
+ // cache lock, so the atomic add is safe. It also records the
key, which is
+ // the only first-hand evidence that a later miss on it is a
re-parse.
+ if l, err := lru.NewWithEvict(size, func(key, value
interface{}) {
c.curBytes.Add(-int64(value.(*cacheValue).cost))
+ c.noteEvicted(key)
}); err == nil {
c.lru = l
}
+ // Sized to match the cache, so a template evicted at any point
while the cache
+ // held its current contents is still recognized when it comes
back. At 8 bytes
+ // per hash this is ~16KB for a 2000-entry cache.
+ if e, err := lru.New(size); err == nil {
+ c.evicted = e
+ }
}
return c
}
+// queryHash keys the evicted set by hash, not by the multi-KB query text: a
hash is
+// 8 bytes and never pins the evicted query's memory, so remembering an
eviction costs
+// almost nothing. Sum64String is allocation-free. A 64-bit collision (~1e-13
at a few
+// thousand keys; zero across a million distinct queries in practice) would
only misreport
+// one first-ever compile as a re-parse — a harmless false positive, never a
missed one.
+func queryHash(query string) uint64 {
+ return xxhash.Sum64String(query)
+}
+
+func (c *preparedCache) noteEvicted(key interface{}) {
+ if c.evicted == nil {
+ return
+ }
+ if q, ok := key.(string); ok {
+ c.evicted.Add(queryHash(q), struct{}{})
+ }
+}
+
+// wasEvicted reports whether query had been cached before and was evicted,
which makes
+// the miss now in flight a re-parse rather than a first-ever compile.
+//
+// Only ever called on the miss path — a hit needs no such check, it is a hit.
Keeping
+// the hash off the hit path leaves the ~98% of traffic that hits untouched;
on a miss it
+// vanishes next to the ~220us parse.
+func (c *preparedCache) wasEvicted(query string) bool {
+ return c.evicted != nil && c.evicted.Contains(queryHash(query))
+}
+
+// cacheResultReparse is the getOrPrepare result for a miss that re-compiled a
template
+// the cache had already compiled once. Only these reach the top-K tracker; to
the metrics
+// and the access log a re-parse is an ordinary miss.
+const cacheResultReparse = "reparse"
+
// getOrPrepare returns the prepared statement for query, parsing and caching
it on
-// a miss. It records the cache metrics internally; the returned result ("hit",
-// "miss", "bypass", or "" for a disabled cache) lets the caller tag the query
-// access log so un-cached queries can be found. Callers handle only the parse
error.
+// a miss. It records the cache metrics internally, and returns a result that
tags the
+// query access log so un-cached queries can be found:
+//
+// "hit" — served from the cache
+// "miss" — a template's unavoidable first-ever compile
+// "reparse" — a miss that re-compiled a template compiled before (evicted
and requested
+// again, or too large to ever cache): real thrashing. Only
the cache can
+// classify this — it reads private eviction state and must
judge before
+// store() perturbs it — but it reports the verdict rather
than acting on it,
+// so the caller drives what happens (the top-K tracker wants
only re-parses,
+// since first-ever compiles are an unavoidable one-off cost).
+// "bypass" — a literal (non-parameterized) query, never cached
+// "" — caching disabled
+//
+// A re-parse is a miss to the metrics and the access log (it is one); only
the returned
+// result string splits the two, so the caller can track thrashing without the
cold
+// starts. Callers handle only the parse error.
func (c *preparedCache) getOrPrepare(query string) (*bydbql.PreparedStatement,
string, error) {
if c.lru != nil {
if v, ok := c.lru.Get(query); ok {
@@ -99,27 +159,38 @@ func (c *preparedCache) getOrPrepare(query string)
(*bydbql.PreparedStatement, s
return ps, "bypass", nil
}
c.misses.Add(1)
- c.store(query, ps)
- c.emit("miss")
+ // Judge BEFORE store(): store's own eviction records a new key, which
on a small or
+ // heavily churning evicted set can displace the very record proving
this was a
+ // re-parse.
+ evicted := c.wasEvicted(query)
+ // A statement too large to ever cache is re-parsed on every single
request — the
+ // worst thrashing there is, and one the evicted set can never witness.
+ cached := c.store(query, ps)
+ c.emit("miss") // metrics fold a re-parse into miss; only the result
string splits them
+ if evicted || !cached {
+ return ps, cacheResultReparse, nil
+ }
return ps, "miss", nil
}
// store caches ps under the byte bound, skipping a statement that alone
exceeds
// maxBytes. ContainsOrAdd inserts atomically only when the key is absent, so
// concurrent misses on the same query count its bytes exactly once. Call only
for
-// an enabled cache and a parameterized query.
-func (c *preparedCache) store(query string, ps *bydbql.PreparedStatement) {
+// an enabled cache and a parameterized query. Reports whether the statement
is now
+// cached: false means it never can be, so every request will re-parse it.
+func (c *preparedCache) store(query string, ps *bydbql.PreparedStatement) bool
{
cost := len(query) + ps.EstimatedSize()
if c.maxBytes > 0 && cost > c.maxBytes {
- return
+ return false
}
if found, _ := c.lru.ContainsOrAdd(query, &cacheValue{ps: ps, cost:
cost}); found {
- return
+ return true
}
c.curBytes.Add(int64(cost))
for c.maxBytes > 0 && c.curBytes.Load() > int64(c.maxBytes) &&
c.lru.Len() > 1 {
c.lru.RemoveOldest()
}
+ return true
}
// emit publishes the cache counter (labeled by result: hit/miss/bypass) and
the
diff --git a/banyand/liaison/grpc/bydbql_reparse_test.go
b/banyand/liaison/grpc/bydbql_reparse_test.go
new file mode 100644
index 000000000..a17675968
--- /dev/null
+++ b/banyand/liaison/grpc/bydbql_reparse_test.go
@@ -0,0 +1,163 @@
+// Licensed to Apache Software Foundation (ASF) under one or more contributor
+// license agreements. See the NOTICE file distributed with
+// this work for additional information regarding copyright
+// ownership. Apache Software Foundation (ASF) licenses this file to you under
+// the Apache License, Version 2.0 (the "License"); you may
+// not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing,
+// software distributed under the License is distributed on an
+// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+// KIND, either express or implied. See the License for the
+// specific language governing permissions and limitations
+// under the License.
+
+package grpc
+
+import (
+ "testing"
+
+ "github.com/stretchr/testify/assert"
+ "github.com/stretchr/testify/require"
+)
+
+// newReparseProbe returns the cache, a tracker, and a run() that drives one
query
+// through the cache exactly as bydbQLService.Query does: it feeds the tracker
only when
+// getOrPrepare reports a re-parse. Tests go through run() rather than
observing the
+// cache directly, so they exercise the real "if reparse" decision and would
catch a
+// change that broke it. run() returns the cache result for assertions.
+func newReparseProbe(t *testing.T, size, maxBytes int) (*preparedCache, *topK,
func(query string) string) {
+ t.Helper()
+ tk := newTopK(bydbqlTopKSize)
+ c := newPreparedCache(size, maxBytes, nil)
+ run := func(q string) string {
+ _, result, err := c.getOrPrepare(q)
+ require.NoError(t, err)
+ if result == cacheResultReparse {
+ tk.observe(q, 0)
+ }
+ return result
+ }
+ return c, tk, run
+}
+
+// The workload that exposed the bug, measured on a live SkyWalking OAP
cluster:
+// 2495 distinct parameterized templates against a cache large enough to hold
them all
+// (2495 entries of ~1.7KB against a 4000-entry / 10MiB bound, so nothing is
ever
+// evicted). Every template is compiled exactly once, so there is no thrashing
at all
+// and the dump must be empty.
+//
+// Before the fix the tracker was fed every miss, including these first-ever
compiles.
+// Past bydbqlTopKSize distinct keys, Space-Saving's "new key inherits the
evicted
+// minimum's count + 1" ratcheted all 128 slots to counts of 19-20, so every
one of them
+// cleared the old count>=2 threshold and the log reported 128 templates as
thrashing.
+// Measured live: {count 20: 23 templates, count 19: 105}.
+func TestReparse_ColdStartCompilesNeverReachTheTracker(t *testing.T) {
+ const distinct = 2495
+ c, tk, run := newReparseProbe(t, 4000, 10<<20)
+
+ for i := 0; i < distinct; i++ {
+ require.Equal(t, "miss", run(bydbqlQuery(i)), "a first-ever
compile is still a cache miss")
+ }
+
+ require.Equal(t, distinct, c.lru.Len(), "nothing was evicted, so
nothing can be a re-parse")
+ assert.Empty(t, tk.snapshot(), "first-ever compiles must not be
reported as thrashing")
+ assert.Empty(t, formatTopK(tk.snapshot(), 1, func(s topKSlot) string {
return s.key }),
+ "the dump must be empty on a cluster that is merely warming its
cache")
+}
+
+// The counterpart: with the cache too small for the working set, the
templates really
+// are re-parsed, and every count must be exact rather than a Space-Saving
artifact.
+func TestReparse_ThrashingIsReportedWithTrueCounts(t *testing.T) {
+ const rounds = 5
+ _, tk, run := newReparseProbe(t, 1, 10<<20) // one slot: A and B evict
each other
+
+ for i := 0; i < rounds; i++ {
+ run(bydbqlQuery(0))
+ run(bydbqlQuery(1))
+ }
+
+ snap := tk.snapshot()
+ require.Len(t, snap, 2)
+ counts := map[string]uint64{snap[0].key: snap[0].count, snap[1].key:
snap[1].count}
+ // Each template is compiled once for free, then re-parsed on every
later round.
+ assert.Equal(t, uint64(rounds-1), counts[bydbqlQuery(0)])
+ assert.Equal(t, uint64(rounds-1), counts[bydbqlQuery(1)])
+}
+
+// A statement too large to ever cache is re-parsed on every single request.
The evicted
+// set can never witness it — it was never in the cache to be evicted — so
getOrPrepare
+// reports the re-parse from store()'s failure to cache it.
+func TestReparse_OversizedStatementIsReportedEveryTime(t *testing.T) {
+ c, tk, run := newReparseProbe(t, 10, 1) // maxBytes=1: nothing is ever
cacheable
+
+ for i := 0; i < 3; i++ {
+ run(bydbqlQuery(0))
+ }
+
+ require.Zero(t, c.lru.Len(), "the statement is never cached")
+ snap := tk.snapshot()
+ require.Len(t, snap, 1)
+ assert.Equal(t, uint64(3), snap[0].count, "every request re-parses it,
including the first")
+}
+
+// Guards the ordering the fix depends on: store() evicts a victim and records
that
+// eviction, which on a full evicted set can displace the record proving the
query now
+// being stored was itself a re-parse. Judging before store() is what keeps
this exact.
+func TestReparse_DetectedEvenWhenStoreDisplacesTheEvidence(t *testing.T) {
+ _, tk, run := newReparseProbe(t, 1, 10<<20) // cache and evicted set
both hold one entry
+
+ run(bydbqlQuery(0)) // compile A
+ run(bydbqlQuery(1)) // compile B, evicting A
+ require.Empty(t, tk.snapshot(), "so far only first-ever compiles")
+
+ // Storing A evicts B and records B, pushing A's own eviction record
out of the
+ // one-entry evicted set. The re-parse must already have been detected
by then.
+ run(bydbqlQuery(0))
+
+ snap := tk.snapshot()
+ require.Len(t, snap, 1)
+ assert.Equal(t, bydbqlQuery(0), snap[0].key)
+ assert.Equal(t, uint64(1), snap[0].count)
+}
+
+// A template evicted once and then requested again was really re-compiled,
and the dump
+// must say so. The old count>=2 threshold existed only to hide cold starts;
now that they
+// are excluded at the source, keeping it would re-hide the very re-parses
that exclusion
+// made visible — and would leave the log LESS sensitive than before the fix,
which
+// surfaced a template on its cold start plus one re-parse.
+func TestReparse_SingleReparseReachesTheDump(t *testing.T) {
+ _, tk, run := newReparseProbe(t, 1, 10<<20)
+
+ run(bydbqlQuery(0)) // cold-start compile
+ run(bydbqlQuery(1)) // evicts it
+ run(bydbqlQuery(0)) // one real re-parse
+
+ lines := formatTopK(tk.snapshot(), 1, func(s topKSlot) string { return
s.key })
+ require.Len(t, lines, 1, "a single genuine re-parse must not be
filtered away")
+ assert.Equal(t, bydbqlQuery(0), lines[0])
+}
+
+// Caching disabled: every request parses, but nothing is a re-parse of a
cached entry,
+// and the cache records neither hits nor misses.
+func TestReparse_SilentWhenCachingDisabled(t *testing.T) {
+ _, tk, run := newReparseProbe(t, 0, 0)
+
+ for i := 0; i < 3; i++ {
+ require.Empty(t, run(bydbqlQuery(0)), "a disabled cache records
no result")
+ }
+ assert.Empty(t, tk.snapshot())
+}
+
+// Literal queries bypass the cache by design and are not re-parses of
anything cached.
+func TestReparse_BypassIsNotAReparse(t *testing.T) {
+ _, tk, run := newReparseProbe(t, 10, 10<<20)
+
+ for i := 0; i < 3; i++ {
+ require.Equal(t, "bypass", run(bydbqlLiteralQuery(0)))
+ }
+ assert.Empty(t, tk.snapshot())
+}
diff --git a/banyand/liaison/grpc/bydbql_test.go
b/banyand/liaison/grpc/bydbql_test.go
index cac5bb4ea..ae92bb8a6 100644
--- a/banyand/liaison/grpc/bydbql_test.go
+++ b/banyand/liaison/grpc/bydbql_test.go
@@ -26,6 +26,7 @@ import (
"github.com/stretchr/testify/require"
"google.golang.org/grpc/codes"
"google.golang.org/grpc/status"
+ "google.golang.org/protobuf/proto"
bydbqlv1
"github.com/apache/skywalking-banyandb/api/proto/banyandb/bydbql/v1"
modelv1
"github.com/apache/skywalking-banyandb/api/proto/banyandb/model/v1"
@@ -94,24 +95,52 @@ func
TestBydbQLQuery_ParamTypeMismatch_ReturnsInvalidArgument(t *testing.T) {
// newTestDumper builds a topKDumper without starting the dump goroutine.
func newTestDumper(l *logger.Logger) *topKDumper {
- return &topKDumper{miss: newTopK(bydbqlTopKSize), slow:
newTopK(bydbqlTopKSize), l: l}
+ return &topKDumper{reparse: newTopK(bydbqlTopKSize), slow:
newTopK(bydbqlTopKSize), l: l}
}
-func TestBydbQLQuery_TracksCacheMiss(t *testing.T) {
- svc := newTestBydbQLService()
+// attachTestDumper gives svc a dumper without starting its dump goroutine, so
the
+// service-level Query path can record re-parses. Query itself decides what to
track
+// (if reparse ...), so no further wiring is needed.
+func attachTestDumper(svc *bydbQLService) {
svc.dumper = newTestDumper(nil)
- // A cacheable query misses on first sight; the miss is observed before
Bind runs
- // (Bind then fails on missing params, but the miss was already
recorded).
+}
+
+// A first-ever compile is not thrashing: every template pays it exactly once,
and it
+// is unavoidable. Tracking it was what buried the real signal and, past
+// bydbqlTopKSize distinct templates, inflated every reported count via
Space-Saving.
+func TestBydbQLQuery_DoesNotTrackColdStartCompile(t *testing.T) {
+ svc := newTestBydbQLService()
+ attachTestDumper(svc)
_, _ = svc.Query(context.Background(), &bydbqlv1.QueryRequest{
Query: "SELECT * FROM STREAM sw IN default WHERE service_id =
?",
})
- assert.NotEmpty(t, svc.dumper.miss.snapshot(), "a cacheable miss must
be tracked")
+ assert.Empty(t, svc.dumper.reparse.snapshot(), "a first-ever compile
must not be tracked")
+}
+
+// A template evicted under cache pressure and then requested again really is
being
+// re-parsed, and that is what the log exists to surface.
+func TestBydbQLQuery_TracksReparseAfterEviction(t *testing.T) {
+ m := newBypassMetrics()
+ svc := &bydbQLService{metrics: m, cache: newPreparedCache(1, 1<<20, m)}
// one slot
+ attachTestDumper(svc)
+ victim := &bydbqlv1.QueryRequest{Query: bydbqlQuery(0)}
+ other := &bydbqlv1.QueryRequest{Query: bydbqlQuery(1)}
+
+ _, _ = svc.Query(context.Background(), victim) // cold-start compile,
not tracked
+ _, _ = svc.Query(context.Background(), other) // evicts victim
+ assert.Empty(t, svc.dumper.reparse.snapshot(), "cold-start compiles
stay untracked")
+
+ _, _ = svc.Query(context.Background(), victim) // victim is back: a
real re-parse
+ snap := svc.dumper.reparse.snapshot()
+ require.Len(t, snap, 1, "only the re-parsed template is tracked")
+ assert.Equal(t, bydbqlQuery(0), snap[0].key)
+ assert.Equal(t, uint64(1), snap[0].count, "count is the true re-parse
count")
}
func TestBydbQLQuery_TracksSlowQuery(t *testing.T) {
svc := newTestBydbQLService()
svc.slowThreshold = time.Nanosecond // any query exceeds it
- svc.dumper = newTestDumper(nil)
+ attachTestDumper(svc)
_, _ = svc.Query(context.Background(), &bydbqlv1.QueryRequest{
Query: "SELECT * FROM STREAM sw IN default WHERE service_id =
?",
})
@@ -120,19 +149,59 @@ func TestBydbQLQuery_TracksSlowQuery(t *testing.T) {
func TestBydbQLDumpTopK(t *testing.T) {
d := newTestDumper(logger.GetLogger("test-bydbql"))
- d.miss.observe("q-miss", 0)
- d.miss.observe("q-miss", 0) // count>=2 so it survives the cold-start
filter
+ d.observeReparse("q-reparse")
+ d.observeReparse("q-reparse") // a second re-parse of the same template
d.slow.observe("q-slow", time.Millisecond)
d.dump() // must not panic; the cumulative trackers keep their entries
- assert.NotEmpty(t, d.miss.snapshot())
+ assert.NotEmpty(t, d.reparse.snapshot())
assert.NotEmpty(t, d.slow.snapshot())
}
-func TestFormatTopKFiltersColdStartMisses(t *testing.T) {
+func TestFormatTopKAppliesItsMinCount(t *testing.T) {
entries := []topKSlot{
- {key: "thrashing", count: 5},
- {key: "cold-start", count: 1},
+ {key: "frequent", count: 5},
+ {key: "once", count: 1},
}
- lines := formatTopK(entries, minReparseMisses, func(s topKSlot) string
{ return s.key })
- assert.Equal(t, []string{"thrashing"}, lines, "count==1 cold-start
misses are filtered out")
+ assert.Equal(t, []string{"frequent"}, formatTopK(entries, 2, func(s
topKSlot) string { return s.key }))
+ // The dumps pass 1, i.e. no filtering: every tracked entry is already
meaningful.
+ assert.Equal(t, []string{"frequent", "once"}, formatTopK(entries, 1,
func(s topKSlot) string { return s.key }))
+}
+
+// captureAccessLog records the service tag of every WriteQuery call.
+type captureAccessLog struct{ services []string }
+
+func (c *captureAccessLog) Write(proto.Message) error { return nil }
+
+func (c *captureAccessLog) WriteQuery(service string, _ time.Time, _
time.Duration, _ proto.Message, _ error) error {
+ c.services = append(c.services, service)
+ return nil
+}
+
+func (c *captureAccessLog) Close() error { return nil }
+
+// A re-parse is a cache miss to anyone searching the access log for un-cached
queries;
+// only the top-K tracker distinguishes it. The access log must therefore tag
it
+// "bydbql-miss", never "bydbql-reparse", or a "bydbql-miss" filter would
silently drop
+// the re-parsed queries — which are exactly the un-cached ones an operator is
after.
+func TestBydbQLQuery_ReparseIsLoggedAsMissNotReparse(t *testing.T) {
+ m := newBypassMetrics()
+ svc := &bydbQLService{metrics: m, cache: newPreparedCache(1, 1<<20, m)}
// one slot
+ attachTestDumper(svc)
+ alog := &captureAccessLog{}
+ svc.queryAccessLog = alog
+
+ // Bind fails (no params), but that is after getOrPrepare set
cacheResult, and the
+ // access log is written from a defer, so every call is logged with its
cache tag.
+ _, _ = svc.Query(context.Background(), &bydbqlv1.QueryRequest{Query:
bydbqlQuery(0)}) // cold-start miss
+ _, _ = svc.Query(context.Background(), &bydbqlv1.QueryRequest{Query:
bydbqlQuery(1)}) // evicts 0
+ _, _ = svc.Query(context.Background(), &bydbqlv1.QueryRequest{Query:
bydbqlQuery(0)}) // re-parse
+
+ require.Len(t, alog.services, 3)
+ assert.Equal(t, "bydbql-miss", alog.services[2], "a re-parse must be
logged as a miss")
+ assert.NotContains(t, alog.services, "bydbql-reparse", "reparse must
never leak into the access log")
+
+ // The distinction survives — but only in the tracker, which is the
whole point.
+ snap := svc.dumper.reparse.snapshot()
+ require.Len(t, snap, 1)
+ assert.Equal(t, bydbqlQuery(0), snap[0].key)
}
diff --git a/banyand/liaison/grpc/server.go b/banyand/liaison/grpc/server.go
index 3c5a347b8..a9425a632 100644
--- a/banyand/liaison/grpc/server.go
+++ b/banyand/liaison/grpc/server.go
@@ -458,7 +458,7 @@ func (s *server) FlagSet() *run.FlagSet {
fs.DurationVar(&s.traceSVC.maxWaitDuration,
"trace-metadata-cache-wait-duration", 0,
"the maximum duration to wait for metadata cache to load (for
testing purposes)")
fs.IntVar(&s.propertyServer.repairQueueCount,
"property-repair-queue-count", 128, "the number of queues for property repair")
- fs.IntVar(&s.bydbqlCacheSize, "bydbql-prepared-cache-size", 2000,
+ fs.IntVar(&s.bydbqlCacheSize, "bydbql-prepared-cache-size", 4000,
"max number of prepared BydbQL statements cached on the query
path; 0 disables the cache")
fs.IntVar(&s.bydbqlCacheMaxBytes, "bydbql-prepared-cache-max-bytes",
10*1024*1024,
"max total estimated size (bytes) of the cached BydbQL prepared
statements; 0 removes the byte bound")
diff --git a/docs/operation/configuration.md b/docs/operation/configuration.md
index 59bd5f636..a4d193329 100644
--- a/docs/operation/configuration.md
+++ b/docs/operation/configuration.md
@@ -91,7 +91,7 @@ The following flags are used to configure the timeout of data
sending from liais
The following flags tune the BydbQL prepared-statement cache on the query
path. The cache stores parsed statements keyed by query text so repeated,
parameterized (`?`) queries skip re-parsing; literal queries without
placeholders are never cached. It is bounded by both an entry count and the
estimated in-memory size of the cached statements, evicting least-recently-used
entries when either bound is exceeded. Effectiveness is observable via the
`bydbql_prepared_cache_*` metrics (a `hit`/` [...]
-- `--bydbql-prepared-cache-size int`: Max number of prepared BydbQL statements
cached on the query path; `0` disables the cache (default: 2000).
+- `--bydbql-prepared-cache-size int`: Max number of prepared BydbQL statements
cached on the query path; `0` disables the cache (default: 4000).
- `--bydbql-prepared-cache-max-bytes int`: Max total estimated size (in bytes)
of the cached prepared statements; `0` removes the byte bound (default:
10485760, i.e. 10MiB).
These flags surface the queries behind cache misses and slow responses without
exposing high-cardinality query text as metric labels: Prometheus gets only two
counters (`bydbql_prepared_cache_total{result="miss"}` and
`bydbql_slow_query_total`), while the specific hot queries are logged.
