tidb/pkg/executor/adapter_slow_log.go

// Copyright 2025 PingCAP, Inc.
//
// Licensed 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 executor

import (
	"bytes"
	"context"
	"strings"
	"sync"
	"time"

	"github.com/pingcap/tidb/pkg/keyspace"
	"github.com/pingcap/tidb/pkg/parser/ast"
	"github.com/pingcap/tidb/pkg/sessionctx/slowlogrule"
	"github.com/pingcap/tidb/pkg/sessionctx/variable"
	"github.com/pingcap/tidb/pkg/util/logutil"
	"github.com/tikv/client-go/v2/util"
	"go.uber.org/zap"
)

func init() {
	variable.SlowLogRuleFieldAccessors[strings.ToLower(variable.SlowLogPlanDigest)] = variable.SlowLogFieldAccessor{
		Parse: variable.ParseString,
		Setter: func(_ context.Context, seVars *variable.SessionVars, items *variable.SlowQueryLogItems) {
			_, planDigest := GetPlanDigest(seVars.StmtCtx)
			items.PlanDigest = planDigest.String()
		},
		Match: func(_ *variable.SessionVars, items *variable.SlowQueryLogItems, threshold any) bool {
			return variable.MatchEqual(threshold, strings.ToLower(items.PlanDigest))
		},
	}
}

var sampleLoggerFactory = logutil.SampleLoggerFactory(time.Minute, 1, zap.String(logutil.LogFieldCategory, "slow log"))

func mergeConditionFields(dst, src map[string]struct{}) {
	for k := range src {
		dst[k] = struct{}{}
	}
}

func updateAllRuleFields(globalRules *slowlogrule.GlobalSlowLogRules, seVars *variable.SessionVars) {
	if seVars.SlowLogRules.NeedUpdateEffectiveFields ||
		globalRules.RawRulesHash != seVars.SlowLogRules.GlobalRawRulesHash {
		allRuleFields := make(map[string]struct{})
		if seVars.SlowLogRules.SlowLogRules != nil {
			mergeConditionFields(allRuleFields, seVars.SlowLogRules.Fields)
		}
		if specificSessionRules, ok := globalRules.RulesMap[int64(seVars.ConnectionID)]; ok {
			mergeConditionFields(allRuleFields, specificSessionRules.Fields)
		}
		if clusterRules, ok := globalRules.RulesMap[variable.UnsetConnID]; ok {
			mergeConditionFields(allRuleFields, clusterRules.Fields)
		}
		seVars.SlowLogRules.EffectiveFields = allRuleFields
		seVars.SlowLogRules.GlobalRawRulesHash = globalRules.RawRulesHash
		seVars.SlowLogRules.NeedUpdateEffectiveFields = false
	}
}

var slowQueryLogItemsPool = sync.Pool{
	New: func() any { return &variable.SlowQueryLogItems{} },
}

func getSlowLogItems() *variable.SlowQueryLogItems {
	return slowQueryLogItemsPool.Get().(*variable.SlowQueryLogItems)
}

func putSlowLogItems(items *variable.SlowQueryLogItems) {
	if items == nil {
		return
	}
	*items = variable.SlowQueryLogItems{}
	slowQueryLogItemsPool.Put(items)
}

// PrepareSlowLogItemsForRules builds a SlowQueryLogItems containing only the fields referenced by the effective slow log rules.
// These pre-collected fields are later used for matching SQL execution details against the rules.
func PrepareSlowLogItemsForRules(ctx context.Context, globalRules *slowlogrule.GlobalSlowLogRules, seVars *variable.SessionVars) *variable.SlowQueryLogItems {
	updateAllRuleFields(globalRules, seVars)
	if len(seVars.SlowLogRules.EffectiveFields) == 0 {
		return nil
	}

	var items *variable.SlowQueryLogItems
	for field := range seVars.SlowLogRules.EffectiveFields {
		if gs, ok := variable.SlowLogRuleFieldAccessors[field]; ok && gs.Setter != nil {
			if items == nil {
				items = getSlowLogItems()
			}
			gs.Setter(ctx, seVars, items)
		}
	}

	return items
}

// Match checks whether the given SlowQueryLogItems satisfies any of the
// current session's slow log trigger rules.
//
// Matching is evaluated in two levels of logical relationship:
//   - Rules are combined with OR: if any rule is satisfied, the function returns true.
//   - Conditions inside a rule are combined with AND: all conditions must be met for that rule.
//
// Returns true if any rule matches, false otherwise.
func Match(seVars *variable.SessionVars, items *variable.SlowQueryLogItems, rules *slowlogrule.SlowLogRules) bool {
	if rules == nil {
		return false
	}

	// Or logical relationship
	for _, rule := range rules.Rules {
		match := true

		// And logical relationship
		for _, condition := range rule.Conditions {
			accessor := variable.SlowLogRuleFieldAccessors[strings.ToLower(condition.Field)]
			if ok := accessor.Match(seVars, items, condition.Threshold); !ok {
				match = false
				break
			}
		}

		if match {
			return true
		}
	}

	return false
}

// ShouldWriteSlowLog determines whether the current query should be written to the slow log.
// The decision is based on the following rule hierarchy:
//
// 1. Session-level rules: if defined, they take precedence.
// 2. Global-level rules:
//   - If a rule specifies a ConnID that matches the current session, it is applied.
//   - If a rule does not specify ConnID (global default), it is also applied.
//
// 3. All applicable rules are combined with logical OR.
//
// Returns true if any rule matches, otherwise false.
func ShouldWriteSlowLog(globalRules *slowlogrule.GlobalSlowLogRules, seVars *variable.SessionVars, items *variable.SlowQueryLogItems) bool {
	if isMatched := Match(seVars, items, seVars.SlowLogRules.SlowLogRules); isMatched {
		return isMatched
	}

	if specificSessionRules, ok := globalRules.RulesMap[int64(seVars.ConnectionID)]; ok {
		if isMatched := Match(seVars, items, specificSessionRules); isMatched {
			return isMatched
		}
	}
	if clusterRules, ok := globalRules.RulesMap[variable.UnsetConnID]; ok {
		if isMatched := Match(seVars, items, clusterRules); isMatched {
			return isMatched
		}
	}

	return false
}

// CompleteSlowLogItemsForRules fills in the remaining fields of SlowQueryLogItems
// that were not required by the session's effective rule set.
// It's exporting for testing.
func CompleteSlowLogItemsForRules(ctx context.Context, seVars *variable.SessionVars, items *variable.SlowQueryLogItems) {
	for field, sg := range variable.SlowLogRuleFieldAccessors {
		if _, ok := seVars.SlowLogRules.EffectiveFields[field]; ok {
			continue
		}

		if sg.Setter != nil {
			sg.Setter(ctx, seVars, items)
		}
	}
}

// SetSlowLogItems fills the remaining fields of SlowQueryLogItems after SQL execution.
func SetSlowLogItems(a *ExecStmt, txnTS uint64, hasMoreResults bool, items *variable.SlowQueryLogItems) {
	if items == nil {
		return
	}
	CompleteSlowLogItemsForRules(a.GoCtx, a.Ctx.GetSessionVars(), items)

	sessVars := a.Ctx.GetSessionVars()
	stmtCtx := sessVars.StmtCtx
	var indexNames string
	if len(stmtCtx.IndexNames) > 0 {
		// remove duplicate index.
		idxMap := make(map[string]struct{})
		buf := bytes.NewBuffer(make([]byte, 0, 4))
		buf.WriteByte('[')
		for _, idx := range stmtCtx.IndexNames {
			_, ok := idxMap[idx]
			if ok {
				continue
			}
			idxMap[idx] = struct{}{}
			if buf.Len() > 1 {
				buf.WriteByte(',')
			}
			buf.WriteString(idx)
		}
		buf.WriteByte(']')
		indexNames = buf.String()
	}

	var ruDetails *util.RUDetails
	if ruDetailsVal := a.GoCtx.Value(util.RUDetailsCtxKey); ruDetailsVal != nil {
		ruDetails = ruDetailsVal.(*util.RUDetails)
	} else {
		ruDetails = util.NewRUDetails()
	}

	binaryPlan := ""
	if variable.GenerateBinaryPlan.Load() {
		binaryPlan = getBinaryPlan(a.Ctx)
		if len(binaryPlan) > 0 {
			binaryPlan = variable.SlowLogBinaryPlanPrefix + binaryPlan + variable.SlowLogPlanSuffix
		}
	}

	var keyspaceID uint32
	keyspaceName := keyspace.GetKeyspaceNameBySettings()
	if !keyspace.IsKeyspaceNameEmpty(keyspaceName) {
		keyspaceID = uint32(a.Ctx.GetStore().GetCodec().GetKeyspaceID())
	}
	if txnTS == 0 {
		// TODO: txnTS maybe ambiguous, consider logging stale-read-ts with a new field in the slow log.
		txnTS = sessVars.TxnCtx.StaleReadTs
	}

	items.TxnTS = txnTS
	items.KeyspaceName = keyspaceName
	items.KeyspaceID = keyspaceID
	items.SQL = FormatSQL(a.GetTextToLog(true)).String()
	items.IndexNames = indexNames
	items.Plan = getPlanTree(stmtCtx)
	items.BinaryPlan = binaryPlan
	items.Prepared = a.isPreparedStmt
	items.HasMoreResults = hasMoreResults
	items.PlanFromCache = sessVars.FoundInPlanCache
	items.PlanFromBinding = sessVars.FoundInBinding
	items.ResultRows = stmtCtx.GetResultRowsCount()
	items.IsExplicitTxn = sessVars.TxnCtx.IsExplicit
	items.IsWriteCacheTable = stmtCtx.WaitLockLeaseTime > 0
	items.UsedStats = stmtCtx.GetUsedStatsInfo(false)
	items.IsSyncStatsFailed = stmtCtx.IsSyncStatsFailed
	items.Warnings = variable.CollectWarningsForSlowLog(stmtCtx)
	items.ResourceGroupName = stmtCtx.ResourceGroupName
	items.RUDetails = ruDetails
	items.CPUUsages = sessVars.SQLCPUUsages.GetCPUUsages()
	items.StorageKV = stmtCtx.IsTiKV.Load()
	items.StorageMPP = stmtCtx.IsTiFlash.Load()
	items.MemArbitration = stmtCtx.MemTracker.MemArbitration().Seconds()

	if a.retryCount > 0 {
		items.ExecRetryTime = items.TimeTotal - sessVars.DurationParse - sessVars.DurationCompile - time.Since(a.retryStartTime)
	}
	if _, ok := a.StmtNode.(*ast.CommitStmt); ok && sessVars.PrevStmt != nil {
		items.PrevStmt = sessVars.PrevStmt.String()
	}
}