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 <[email protected]> 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) }
