Skip to content
Merged
Show file tree
Hide file tree
Changes from 1 commit
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 6 additions & 0 deletions pkg/sessionctx/vardef/tidb_vars.go
Original file line number Diff line number Diff line change
Expand Up @@ -704,6 +704,11 @@ const (
// TiDBStmtSummaryMaxSQLLength indicates the max length of displayed normalized sql and sample sql.
TiDBStmtSummaryMaxSQLLength = "tidb_stmt_summary_max_sql_length"

// TiDBStmtSummaryLogEvicted controls whether per-record LRU evictions in
// the v2 (persistent) statement summary are written to the stmt log. Off
// by default because it adds log volume proportional to eviction rate.
TiDBStmtSummaryLogEvicted = "tidb_stmt_summary_log_evicted"

// TiDBIgnoreInlistPlanDigest enables TiDB to generate the same plan digest with SQL using different in-list arguments.
TiDBIgnoreInlistPlanDigest = "tidb_ignore_inlist_plan_digest"

Expand Down Expand Up @@ -1588,6 +1593,7 @@ const (
DefTiDBStmtSummaryHistorySize = 24
DefTiDBStmtSummaryMaxStmtCount = 3000
DefTiDBStmtSummaryMaxSQLLength = 32768
DefTiDBStmtSummaryLogEvicted = false
DefTiDBCapturePlanBaseline = Off
DefTiDBIgnoreInlistPlanDigest = true
DefTiDBEnableIndexMerge = true
Expand Down
4 changes: 4 additions & 0 deletions pkg/sessionctx/variable/sysvar.go
Original file line number Diff line number Diff line change
Expand Up @@ -942,6 +942,10 @@ var defaultSysVars = []*SysVar{
SetGlobal: func(_ context.Context, s *SessionVars, val string) error {
return stmtsummaryv2.SetMaxSQLLength(TidbOptInt(val, vardef.DefTiDBStmtSummaryMaxSQLLength))
}},
{Scope: vardef.ScopeGlobal, Name: vardef.TiDBStmtSummaryLogEvicted, Value: BoolToOnOff(vardef.DefTiDBStmtSummaryLogEvicted), Type: vardef.TypeBool, AllowEmpty: true,
SetGlobal: func(_ context.Context, s *SessionVars, val string) error {
return stmtsummaryv2.SetLogEvicted(TiDBOptOn(val))
}},
{Scope: vardef.ScopeGlobal, Name: vardef.TiDBCapturePlanBaseline, Value: vardef.DefTiDBCapturePlanBaseline, Type: vardef.TypeBool, AllowEmptyAll: true},
{Scope: vardef.ScopeGlobal, Name: vardef.TiDBEvolvePlanTaskMaxTime, Value: strconv.Itoa(vardef.DefTiDBEvolvePlanTaskMaxTime), Type: vardef.TypeInt, MinValue: -1, MaxValue: math.MaxInt64},
{Scope: vardef.ScopeGlobal, Name: vardef.TiDBEvolvePlanTaskStartTime, Value: vardef.DefTiDBEvolvePlanTaskStartTime, Type: vardef.TypeTime},
Expand Down
2 changes: 1 addition & 1 deletion pkg/util/stmtsummary/v2/BUILD.bazel
Original file line number Diff line number Diff line change
Expand Up @@ -48,7 +48,7 @@ go_test(
],
embed = [":stmtsummary"],
flaky = True,
shard_count = 13,
shard_count = 14,
deps = [
"//pkg/meta/model",
"//pkg/parser/ast",
Expand Down
20 changes: 20 additions & 0 deletions pkg/util/stmtsummary/v2/logger.go
Original file line number Diff line number Diff line change
Expand Up @@ -70,6 +70,26 @@ func (s *stmtLogStorage) sync() error {
return s.logger.Sync()
}

// logEvicted writes a single evicted record to the stmt log with an
// `"evicted":true` marker so downstream consumers can distinguish per-record
// eviction events from rotated-window records.
func (s *stmtLogStorage) logEvicted(r *StmtRecord) {
b, err := json.Marshal(evictedStmtRecord{StmtRecord: r, Evicted: true})
if err != nil {
logutil.BgLogger().Warn("failed to marshal evicted statement summary", zap.Error(err))
return
}
s.logger.Info(string(b))
}

// evictedStmtRecord embeds *StmtRecord and adds an "evicted" JSON tag.
// Keeping the embedded pointer means the JSON field order matches StmtRecord
// and parsers tolerant of the extra field work unchanged.
type evictedStmtRecord struct {
*StmtRecord
Evicted bool `json:"evicted"`
}

func (s *stmtLogStorage) log(r *StmtRecord) {
b, err := json.Marshal(r)
if err != nil {
Expand Down
159 changes: 153 additions & 6 deletions pkg/util/stmtsummary/v2/stmtsummary.go
Original file line number Diff line number Diff line change
Expand Up @@ -40,6 +40,10 @@ const (
defaultMaxSQLLength = 32768
defaultRefreshInterval = 30 * 60 // 30 min
defaultRotateCheckInterval = 1 // s

// evictedLogChanCap bounds the buffer of per-record evicted entries waiting
// to be logged. When full, new evictions are dropped so Add() never blocks.
evictedLogChanCap = 1024
)

var (
Expand Down Expand Up @@ -85,12 +89,18 @@ type StmtSummary struct {
optMaxStmtCount *atomic2.Uint32
optMaxSQLLength *atomic2.Uint32
optRefreshInterval *atomic2.Uint32
optLogEvicted *atomic2.Bool

window *stmtWindow
windowLock sync.Mutex
storage stmtStorage
closeWg sync.WaitGroup
closed atomic.Bool

// evictedCh carries per-record evictions to the async logger.
// A nil channel means evicted-logging is disabled. Sends are non-blocking.
evictedCh chan *StmtRecord

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Actually,even if evicted-logging is disabled, the channel seems non-nil, the comment is a little miss-leading.

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Addressed in the current version: the comment now says eviction persistence is controlled by optPersistEvicted, and evictedCh only carries records to the async logger with non-blocking sends.

evictedDropped atomic.Uint64
}

// NewStmtSummary creates a new StmtSummary from Config.
Expand All @@ -112,7 +122,7 @@ func NewStmtSummary(cfg *Config) (*StmtSummary, error) {
optMaxStmtCount: atomic2.NewUint32(defaultMaxStmtCount),
optMaxSQLLength: atomic2.NewUint32(defaultMaxSQLLength),
optRefreshInterval: atomic2.NewUint32(defaultRefreshInterval),
window: newStmtWindow(timeNow(), uint(defaultMaxStmtCount)),
optLogEvicted: atomic2.NewBool(false),
storage: newStmtLogStorage(&log.Config{
File: log.FileLogConfig{
Filename: cfg.Filename,
Expand All @@ -121,13 +131,20 @@ func NewStmtSummary(cfg *Config) (*StmtSummary, error) {
MaxBackups: cfg.FileMaxBackups,
},
}),
evictedCh: make(chan *StmtRecord, evictedLogChanCap),
}
s.window = newStmtWindow(timeNow(), uint(defaultMaxStmtCount), s.onEvict)

s.closeWg.Add(1)
go func() {
defer s.closeWg.Done()
s.rotateLoop()
}()
s.closeWg.Add(1)
go func() {
defer s.closeWg.Done()
s.evictedLogLoop()
}()

return s, nil
}
Expand All @@ -145,9 +162,17 @@ func NewStmtSummary4Test(maxStmtCount uint) *StmtSummary {
optMaxStmtCount: atomic2.NewUint32(defaultMaxStmtCount),
optMaxSQLLength: atomic2.NewUint32(defaultMaxSQLLength),
optRefreshInterval: atomic2.NewUint32(60 * 60 * 24 * 365), // 1 year
window: newStmtWindow(timeNow(), maxStmtCount),
optLogEvicted: atomic2.NewBool(false),
storage: &mockStmtStorage{},
evictedCh: make(chan *StmtRecord, evictedLogChanCap),
}
ss.window = newStmtWindow(timeNow(), maxStmtCount, ss.onEvict)

ss.closeWg.Add(1)
go func() {
defer ss.closeWg.Done()
ss.evictedLogLoop()
}()

return ss
}
Expand Down Expand Up @@ -234,6 +259,17 @@ func (s *StmtSummary) SetRefreshInterval(v uint32) error {
return nil
}

// LogEvicted reports whether per-record evictions are logged.
func (s *StmtSummary) LogEvicted() bool {
return s.optLogEvicted.Load()
}

// SetLogEvicted enables or disables per-record eviction logging.
func (s *StmtSummary) SetLogEvicted(v bool) error {
s.optLogEvicted.Store(v)
return nil
}

// Add adds a single stmtsummary.StmtExecInfo to the current statistics window
// of StmtSummary. Before adding, it will check whether the current window has
// expired, and if it has expired, the window will be persisted asynchronously
Expand Down Expand Up @@ -318,7 +354,7 @@ func (s *StmtSummary) flush() {

s.windowLock.Lock()
window := s.window
s.window = newStmtWindow(now, uint(s.MaxStmtCount()))
s.window = newStmtWindow(now, uint(s.MaxStmtCount()), s.onEvict)
s.windowLock.Unlock()

if window.lru.Size() > 0 {
Expand Down Expand Up @@ -352,7 +388,7 @@ func (s *StmtSummary) rotateLoop() {

func (s *StmtSummary) rotate(now time.Time) {
w := s.window
s.window = newStmtWindow(now, uint(s.MaxStmtCount()))
s.window = newStmtWindow(now, uint(s.MaxStmtCount()), s.onEvict)
size := w.lru.Size()
if size > 0 {
// Persist window asynchronously.
Expand All @@ -364,6 +400,66 @@ func (s *StmtSummary) rotate(now time.Time) {
}
}

// onEvict is the LRU eviction hook installed on every stmtWindow.
// Called while the record's lock is held (see newStmtWindow). We copy the
// fields we need and hand the clone off to the async log goroutine. A
// non-blocking send is used so the hot Add() path never stalls on log I/O.
func (s *StmtSummary) onEvict(_ *stmtsummary.StmtDigestKey, r *StmtRecord) {
if !s.optLogEvicted.Load() {
return
}
if s.evictedCh == nil {
return
}
clone := cloneRecordForLog(r)
select {
case s.evictedCh <- clone:
default:
s.evictedDropped.Add(1)
}
}

// evictedLogLoop drains evictedCh and writes each record to the stmt log.
// When group_by_user is also enabled, each logged record represents exactly
// one (digest, user) group that fell out of the LRU.
func (s *StmtSummary) evictedLogLoop() {
const dropReportInterval = 30 * time.Second
ticker := time.NewTicker(dropReportInterval)
defer ticker.Stop()

var lastDropReport uint64
report := func() {
cur := s.evictedDropped.Load()
if cur > lastDropReport {
logutil.BgLogger().Warn("stmt summary evicted log dropped records",
zap.Uint64("dropped_total", cur),
zap.Uint64("since_last_report", cur-lastDropReport),
)
lastDropReport = cur
}
}

for {
select {
case <-s.ctx.Done():
// Drain remaining buffered records synchronously, then exit.
for {
select {
case r := <-s.evictedCh:
s.storage.logEvicted(r)
default:
report()
return
}
}
case r := <-s.evictedCh:
s.storage.logEvicted(r)
case <-ticker.C:
report()
}
}
Comment thread
nolouch marked this conversation as resolved.
}

// stmtWindow represents a single statistical window, which has a begin
// time and an end time. Data within a single window is eliminated
// according to the LRU strategy. All evicted data will be aggregated
Expand All @@ -374,7 +470,12 @@ type stmtWindow struct {
evicted *stmtEvicted
}

func newStmtWindow(begin time.Time, capacity uint) *stmtWindow {
// onEvictFn is invoked for every LRU eviction after the evicted stats have
// been aggregated into stmtWindow.evicted. The callback receives the locked
// record (caller holds r.Lock) so it can copy fields cheaply. Must not block.
type onEvictFn func(key *stmtsummary.StmtDigestKey, r *StmtRecord)

func newStmtWindow(begin time.Time, capacity uint, onEvict onEvictFn) *stmtWindow {
w := &stmtWindow{
begin: begin,
lru: kvcache.NewSimpleLRUCache(capacity, 0, 0),
Expand All @@ -384,7 +485,11 @@ func newStmtWindow(begin time.Time, capacity uint) *stmtWindow {
r := v.(*lockedStmtRecord)
r.Lock()
defer r.Unlock()
w.evicted.add(k.(*stmtsummary.StmtDigestKey), r.StmtRecord)
key := k.(*stmtsummary.StmtDigestKey)
w.evicted.add(key, r.StmtRecord)
if onEvict != nil {
onEvict(key, r.StmtRecord)
}
})
return w
}
Expand All @@ -396,6 +501,10 @@ func (w *stmtWindow) clear() {

type stmtStorage interface {
persist(w *stmtWindow, end time.Time)
// logEvicted writes a single evicted record to durable storage. It may be
// called concurrently with persist; implementations must be safe to call
// from the evictedLogLoop goroutine.
logEvicted(r *StmtRecord)
sync() error
}

Expand Down Expand Up @@ -442,6 +551,7 @@ type lockedStmtRecord struct {
type mockStmtStorage struct {
sync.Mutex
windows []*stmtWindow
evicted []*StmtRecord
}

func (s *mockStmtStorage) persist(w *stmtWindow, _ time.Time) {
Expand All @@ -450,10 +560,38 @@ func (s *mockStmtStorage) persist(w *stmtWindow, _ time.Time) {
s.Unlock()
}

func (s *mockStmtStorage) logEvicted(r *StmtRecord) {
s.Lock()
s.evicted = append(s.evicted, r)
s.Unlock()
}

func (*mockStmtStorage) sync() error {
return nil
}

// cloneRecordForLog returns a shallow copy of r with its two mutable maps
// (AuthUsers, BackoffTypes) cloned, so the async logger can marshal the
// snapshot without racing with further updates on the retained StmtRecord.
// Called with r's lock held (see onEvict).
func cloneRecordForLog(r *StmtRecord) *StmtRecord {
c := *r
if len(r.AuthUsers) > 0 {
c.AuthUsers = make(map[string]struct{}, len(r.AuthUsers))
for u := range r.AuthUsers {
c.AuthUsers[u] = struct{}{}
}
}
if len(r.BackoffTypes) > 0 {
c.BackoffTypes = make(map[string]int, len(r.BackoffTypes))
for k, v := range r.BackoffTypes {
c.BackoffTypes[k] = v
}
}
// IndexNames is a slice; shallow copy is fine because it is append-only.
return &c
}

/* Public proxy functions between v1 and v2 */

// Add wraps GlobalStmtSummary.Add and stmtsummary.StmtSummaryByDigestMap.AddStatement.
Expand Down Expand Up @@ -529,3 +667,12 @@ func SetMaxSQLLength(v int) error {
}
return stmtsummary.StmtSummaryByDigestMap.SetMaxSQLLength(v)
}

// SetLogEvicted toggles per-record eviction logging. Only v2 (persistent)
// honors this flag; v1 has no log sink, so the call is a no-op for it.
func SetLogEvicted(v bool) error {
if GlobalStmtSummary != nil {
return GlobalStmtSummary.SetLogEvicted(v)
}
return nil
}
36 changes: 36 additions & 0 deletions pkg/util/stmtsummary/v2/stmtsummary_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -17,6 +17,7 @@ package stmtsummary
import (
"encoding/json"
"testing"
"time"

"github.com/stretchr/testify/require"
)
Expand Down Expand Up @@ -69,6 +70,41 @@ func TestStmtSummary(t *testing.T) {
require.Equal(t, 0, w.lru.Size())
}

func TestStmtSummaryLogEvicted(t *testing.T) {
storage := &mockStmtStorage{}
ss := NewStmtSummary4Test(2)
ss.storage = storage
defer ss.Close()
require.NoError(t, ss.SetLogEvicted(true))

// With capacity 2, the 3rd and later distinct digests evict older entries
// and should each land in storage.evicted.
ss.Add(GenerateStmtExecInfo4Test("digest1"))
ss.Add(GenerateStmtExecInfo4Test("digest2"))
ss.Add(GenerateStmtExecInfo4Test("digest3")) // evicts digest1
ss.Add(GenerateStmtExecInfo4Test("digest4")) // evicts digest2

// The log is async; wait briefly for drain.
require.Eventually(t, func() bool {
storage.Lock()
defer storage.Unlock()
return len(storage.evicted) == 2
}, time.Second, 10*time.Millisecond, "expected 2 evicted records to be logged")

storage.Lock()
digests := []string{storage.evicted[0].Digest, storage.evicted[1].Digest}
storage.Unlock()
require.ElementsMatch(t, []string{"digest1", "digest2"}, digests)

// Disable and verify no further log writes.
require.NoError(t, ss.SetLogEvicted(false))
ss.Add(GenerateStmtExecInfo4Test("digest5")) // evicts digest3
time.Sleep(50 * time.Millisecond)
storage.Lock()
require.Equal(t, 2, len(storage.evicted))
storage.Unlock()
}

func TestStmtSummaryFlush(t *testing.T) {
storage := &mockStmtStorage{}
ss := NewStmtSummary4Test(1000)
Expand Down