You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@skywalking.apache.org by li...@apache.org on 2026/07/17 07:34:13 UTC
(skywalking-banyandb) 01/01: Fix wrong QL cache miss top-K logs
This is an automated email from the ASF dual-hosted git repository.
mrproliu pushed a commit to branch ql-miss-log
in repository https://gitbox.apache.org/repos/asf/skywalking-banyandb.git
commit 3192a3487c79b972e0fb162ef4f374a5418653a4
Author: mrproliu <74...@qq.com>
AuthorDate: Fri Jul 17 15:33:51 2026 +0800
Fix wrong QL cache miss top-K logs
---
banyand/liaison/grpc/bydbql.go | 55 +++++++---
banyand/liaison/grpc/bydbql_cache.go | 92 +++++++++++++---
banyand/liaison/grpc/bydbql_reparse_test.go | 163 ++++++++++++++++++++++++++++
banyand/liaison/grpc/bydbql_test.go | 101 ++++++++++++++---
4 files changed, 366 insertions(+), 45 deletions(-)
diff --git a/banyand/liaison/grpc/bydbql.go b/banyand/liaison/grpc/bydbql.go
index 97e714ac9..61b7eec1c 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 == "reparse" {
+ 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 == "reparse" {
+ 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..e40cf0ca8 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 recognised 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,70 @@ 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 recognised 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))
+}
+
// 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 +154,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, "reparse", 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..ac3861563
--- /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 == "reparse" {
+ 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..9f5ef3c6d 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,54 @@ 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) {
+// 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, l *logger.Logger) *topKDumper {
+ d := newTestDumper(l)
+ svc.dumper = d
+ return d
+}
+
+// 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()
- 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).
+ attachTestDumper(svc, nil)
_, _ = 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, nil)
+ 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, nil)
_, _ = svc.Query(context.Background(), &bydbqlv1.QueryRequest{
Query: "SELECT * FROM STREAM sw IN default WHERE service_id = ?",
})
@@ -120,19 +151,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, nil)
+ 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)
}