Skip to content

executor, infoschema, sessionctx, util: split RUv2 slow log output #67278

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
ti-chi-bot merged 3 commits into from
Mar 25, 2026
Merged

executor, infoschema, sessionctx, util: split RUv2 slow log output #67278

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
6e94afe
executor, infoschema, sessionctx, util: split RUv2 slow log output
disksing Mar 25, 2026
4f0e9b8
executor: add slow query RUv2 end-to-end test
disksing Mar 25, 2026
7732397
sessionctx, util: avoid duplicate RUv2 slow log formatting
disksing Mar 25, 2026
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
8 changes: 6 additions & 2 deletions pkg/executor/slow_query.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -985,6 +985,9 @@ func (e *slowQueryRetriever) parseLog(ctx context.Context, sctx sessionctx.Conte
} else if strings.HasPrefix(line, variable.SlowLogSessionConnectAttrs+variable.SlowLogSpaceMarkStr) {
line = line[len(variable.SlowLogSessionConnectAttrs+variable.SlowLogSpaceMarkStr):]
valid = e.setColumnValue(sctx, row, tz, variable.SlowLogSessionConnectAttrs, line, e.checker, fileLine)
} else if strings.HasPrefix(line, variable.SlowLogRequestUnitV2Detail+variable.SlowLogSpaceMarkStr) {
Comment thread
disksing marked this conversation as resolved.
line = line[len(variable.SlowLogRequestUnitV2Detail+variable.SlowLogSpaceMarkStr):]
valid = e.setColumnValue(sctx, row, tz, variable.SlowLogRequestUnitV2Detail, line, e.checker, fileLine)
Comment thread
coderabbitai[bot] marked this conversation as resolved.
} else if strings.HasPrefix(line, variable.SlowLogDBStr+variable.SlowLogSpaceMarkStr) {
line = line[len(variable.SlowLogDBStr+variable.SlowLogSpaceMarkStr):]
valid = e.setColumnValue(sctx, row, tz, variable.SlowLogDBStr, line, e.checker, fileLine)
Expand Down Expand Up @@ -1133,7 +1136,8 @@ func getColumnValueFactoryByName(colName string, columnIdx int) (slowQueryColumn
execdetails.LockKeysTimeStr, variable.SlowLogCopProcAvg, variable.SlowLogCopProcP90, variable.SlowLogCopProcMax,
variable.SlowLogCopWaitAvg, variable.SlowLogCopWaitP90, variable.SlowLogCopWaitMax, variable.SlowLogKVTotal,
variable.SlowLogPDTotal, variable.SlowLogBackoffTotal, variable.SlowLogWriteSQLRespTotal, variable.SlowLogRRU,
variable.SlowLogWRU, variable.SlowLogWaitRUDuration, variable.SlowLogTidbCPUUsageDuration, variable.SlowLogTikvCPUUsageDuration, variable.SlowLogMemArbitration:
variable.SlowLogWRU, variable.SlowLogWaitRUDuration, variable.SlowLogTidbCPUUsageDuration, variable.SlowLogTikvCPUUsageDuration,
variable.SlowLogMemArbitration, variable.SlowLogRequestUnitV2:
return func(row []types.Datum, value string, _ *time.Location, _ *slowLogChecker) (valid bool, err error) {
v, err := strconv.ParseFloat(value, 64)
if err != nil {
Expand All @@ -1145,7 +1149,7 @@ func getColumnValueFactoryByName(colName string, columnIdx int) (slowQueryColumn
case variable.SlowLogUserStr, variable.SlowLogHostStr, execdetails.BackoffTypesStr, variable.SlowLogDBStr, variable.SlowLogIndexNamesStr, variable.SlowLogDigestStr,
variable.SlowLogStatsInfoStr, variable.SlowLogCopProcAddr, variable.SlowLogCopWaitAddr, variable.SlowLogPlanDigest,
variable.SlowLogPrevStmt, variable.SlowLogQuerySQLStr, variable.SlowLogWarnings, variable.SlowLogSessAliasStr,
variable.SlowLogResourceGroup, variable.SlowLogRUV2Metrics:
variable.SlowLogResourceGroup, variable.SlowLogRequestUnitV2Detail:
return func(row []types.Datum, value string, _ *time.Location, _ *slowLogChecker) (valid bool, err error) {
row[columnIdx] = types.NewStringDatum(value)
return true, nil
Expand Down
6 changes: 4 additions & 2 deletions pkg/executor/slow_query_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -165,6 +165,8 @@ func TestParseSlowLogFile(t *testing.T) {
# Tikv_cpu_time: 0.021
# Storage_from_kv: true
# Storage_from_mpp: true
# Request_unit_v2: 150.00
# Request_unit_v2_detail: total_ru:150.00, tidb_ru:0.00, tikv_ru:100.00, tiflash_ru:50.00
# Plan_digest: 60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4
# Prev_stmt: update t set i = 1;
use test;
Expand All @@ -191,7 +193,7 @@ select * from t;`
`0,0,0,0,0,0,0,0,0,0,0,0,,0,0,0,0,0,0,0.38,0.021,0,0,0,1,637,0,10,10,10,10,100,,,1,42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772,t1:1,t2:2,` +
`0.1,0.2,0.03,127.0.0.1:20160,0.05,0.6,0.8,0.0.0.0:20160,70724,23333,65536,0,0,0,30000,3000,10000,1000,500000,500005,300000,300005,0,0,,` +
`Cop_backoff_regionMiss_total_times: 200 Cop_backoff_regionMiss_total_time: 0.2 Cop_backoff_regionMiss_max_time: 0.2 Cop_backoff_regionMiss_max_addr: 127.0.0.1 Cop_backoff_regionMiss_avg_time: 0.2 Cop_backoff_regionMiss_p90_time: 0.2 Cop_backoff_rpcPD_total_times: 200 Cop_backoff_rpcPD_total_time: 0.2 Cop_backoff_rpcPD_max_time: 0.2 Cop_backoff_rpcPD_max_addr: 127.0.0.1 Cop_backoff_rpcPD_avg_time: 0.2 Cop_backoff_rpcPD_p90_time: 0.2 Cop_backoff_rpcTiKV_total_times: 200 Cop_backoff_rpcTiKV_total_time: 0.2 Cop_backoff_rpcTiKV_max_time: 0.2 Cop_backoff_rpcTiKV_max_addr: 127.0.0.1 Cop_backoff_rpcTiKV_avg_time: 0.2 Cop_backoff_rpcTiKV_p90_time: 0.2,` +
`0,0,1,0,1,1,0,default,2.158,2.123,0.05,0.01,0.021,1,1,,,60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4,` +
`0,0,1,0,1,1,0,default,2.158,2.123,0.05,0.01,0.021,1,1,150,total_ru:150.00, tidb_ru:0.00, tikv_ru:100.00, tiflash_ru:50.00,,60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4,` +
`,update t set i = 1;,null,select * from t;`
require.Equal(t, expectRecordString, recordString)

Expand All @@ -214,7 +216,7 @@ select * from t;`
`0,0,0,0,0,0,0,0,0,0,0,0,,0,0,0,0,0,0,0.38,0.021,0,0,0,1,637,0,10,10,10,10,100,,,1,42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772,t1:1,t2:2,` +
`0.1,0.2,0.03,127.0.0.1:20160,0.05,0.6,0.8,0.0.0.0:20160,70724,23333,65536,0,0,0,30000,3000,10000,1000,500000,500005,300000,300005,0,0,,` +
`Cop_backoff_regionMiss_total_times: 200 Cop_backoff_regionMiss_total_time: 0.2 Cop_backoff_regionMiss_max_time: 0.2 Cop_backoff_regionMiss_max_addr: 127.0.0.1 Cop_backoff_regionMiss_avg_time: 0.2 Cop_backoff_regionMiss_p90_time: 0.2 Cop_backoff_rpcPD_total_times: 200 Cop_backoff_rpcPD_total_time: 0.2 Cop_backoff_rpcPD_max_time: 0.2 Cop_backoff_rpcPD_max_addr: 127.0.0.1 Cop_backoff_rpcPD_avg_time: 0.2 Cop_backoff_rpcPD_p90_time: 0.2 Cop_backoff_rpcTiKV_total_times: 200 Cop_backoff_rpcTiKV_total_time: 0.2 Cop_backoff_rpcTiKV_max_time: 0.2 Cop_backoff_rpcTiKV_max_addr: 127.0.0.1 Cop_backoff_rpcTiKV_avg_time: 0.2 Cop_backoff_rpcTiKV_p90_time: 0.2,` +
`0,0,1,0,1,1,0,default,2.158,2.123,0.05,0.01,0.021,1,1,,,60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4,` +
`0,0,1,0,1,1,0,default,2.158,2.123,0.05,0.01,0.021,1,1,150,total_ru:150.00, tidb_ru:0.00, tikv_ru:100.00, tiflash_ru:50.00,,60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4,` +
`,update t set i = 1;,null,select * from t;`
require.Equal(t, expectRecordString, recordString)

Expand Down
3 changes: 2 additions & 1 deletion pkg/infoschema/tables.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -979,7 +979,8 @@ var slowQueryCols = []columnInfo{
{name: variable.SlowLogTikvCPUUsageDuration, tp: mysql.TypeDouble, size: 22},
{name: variable.SlowLogStorageFromKV, tp: mysql.TypeTiny, size: 1},
{name: variable.SlowLogStorageFromMPP, tp: mysql.TypeTiny, size: 1},
{name: variable.SlowLogRUV2Metrics, tp: mysql.TypeLongBlob, size: types.UnspecifiedLength},
{name: variable.SlowLogRequestUnitV2, tp: mysql.TypeDouble, size: 22},
Comment thread
disksing marked this conversation as resolved.
{name: variable.SlowLogRequestUnitV2Detail, tp: mysql.TypeLongBlob, size: types.UnspecifiedLength},
Comment thread
disksing marked this conversation as resolved.
{name: variable.SlowLogPlan, tp: mysql.TypeLongBlob, size: types.UnspecifiedLength},
{name: variable.SlowLogPlanDigest, tp: mysql.TypeVarchar, size: 128},
{name: variable.SlowLogBinaryPlan, tp: mysql.TypeLongBlob, size: types.UnspecifiedLength},
Expand Down
2 changes: 2 additions & 0 deletions pkg/infoschema/test/clustertablestest/tables_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -491,6 +491,7 @@ func TestSlowQuery(t *testing.T) {
"0",
"0",
"0",
"0",
"",
"abcd",
"60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4",
Expand Down Expand Up @@ -586,6 +587,7 @@ func TestSlowQuery(t *testing.T) {
"0.021",
"1",
"1",
"0",
"",
"",
"",
Expand Down
11 changes: 8 additions & 3 deletions pkg/sessionctx/variable/slow_log.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -144,8 +144,10 @@ const (
SlowLogStorageFromKV = "Storage_from_kv"
// SlowLogStorageFromMPP is used to indicate whether the statement read data from TiFlash.
SlowLogStorageFromMPP = "Storage_from_mpp"
// SlowLogRUV2Metrics is the RU v2 metrics for the statement.
SlowLogRUV2Metrics = "RUv2_metrics"
// SlowLogRequestUnitV2 is the RU v2 total for the statement.
SlowLogRequestUnitV2 = "Request_unit_v2"
// SlowLogRequestUnitV2Detail is the RU v2 detailed metrics for the statement.
SlowLogRequestUnitV2Detail = "Request_unit_v2_detail"

// The following constants define the set of fields for SlowQueryLogItems
// that are relevant to evaluating and triggering SlowLogRules.
Expand Down Expand Up @@ -565,8 +567,11 @@ func (s *SessionVars) SlowLogFormat(logItems *SlowQueryLogItems) string {
tiKVRU = logItems.RUDetails.TiKVRUV2()
tiFlashRU = logItems.RUDetails.TiflashRU()
}
if total := execdetails.FormatRUV2Total(logItems.RUV2Metrics, s.RUV2Weights(), tiKVRU, tiFlashRU); len(total) > 0 {
Comment thread
disksing marked this conversation as resolved.
Outdated
writeSlowLogItem(&buf, SlowLogRequestUnitV2, total)
}
if formatted := execdetails.FormatRUV2Metrics(logItems.RUV2Metrics, s.RUV2Weights(), tiKVRU, tiFlashRU); len(formatted) > 0 {
writeSlowLogItem(&buf, SlowLogRUV2Metrics, formatted)
writeSlowLogItem(&buf, SlowLogRequestUnitV2Detail, formatted)
}
if len(logItems.SessionConnectAttrs) > 0 {
// Encode into a temporary buffer first so that a (practically impossible)
Expand Down
3 changes: 2 additions & 1 deletion pkg/sessionctx/variable/tests/session_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -455,7 +455,8 @@ func TestSlowLogFormatIncludesTiFlashRUInRUV2Metrics(t *testing.T) {
logItems.RUDetails.UpdateTiFlash(&rmpb.Consumption{RRU: 20, WRU: 30})

logString := seVar.SlowLogFormat(logItems)
require.Contains(t, logString, "# RUv2_metrics: total_ru:150.00, tidb_ru:0.00, tikv_ru:100.00, tiflash_ru:50.00")
require.Contains(t, logString, "# Request_unit_v2: 150.00")
require.Contains(t, logString, "# Request_unit_v2_detail: total_ru:150.00, tidb_ru:0.00, tikv_ru:100.00, tiflash_ru:50.00")

t.Run("default session weights come from config defaults", func(t *testing.T) {
original := config.GetGlobalConfig()
Expand Down
2 changes: 2 additions & 0 deletions pkg/util/execdetails/execdetails_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -399,8 +399,10 @@ func TestFormatRUV2MetricsIncludesRUValuesFirst(t *testing.T) {
metrics.AddResultChunkCells(1000)
metrics.AddResourceManagerWriteCnt(20)
metrics.AddTiKVCoprocessorWorkTotal("BatchTopN", 10)
total := FormatRUV2Total(metrics, weights, 10987, 246)
formatted := FormatRUV2Metrics(metrics, weights, 10987, 246)

require.Equal(t, "19983.42", total)
require.Contains(t, formatted, "tidb_ru:")
require.Contains(t, formatted, "tikv_ru:")
require.Contains(t, formatted, "tiflash_ru:")
Expand Down
10 changes: 9 additions & 1 deletion pkg/util/execdetails/ruv2_metrics.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -477,7 +477,15 @@ func sumRUV2LabelMap(values map[string]int64) int64 {
return total
}

// FormatRUV2Metrics formats RUv2 metrics into a compact string.
// FormatRUV2Total formats the RUv2 total into a slow log string.
func FormatRUV2Total(metrics *RUV2Metrics, weights RUV2Weights, tiKVRU, tiFlashRU float64) string {
if (metrics == nil || metrics.IsZero()) && tiKVRU == 0 && tiFlashRU == 0 {
return ""
}
return fmt.Sprintf("%.2f", metrics.TotalRU(weights, tiKVRU, tiFlashRU))
}

// FormatRUV2Metrics formats RUv2 metrics into a compact detail string.
func FormatRUV2Metrics(metrics *RUV2Metrics, weights RUV2Weights, tiKVRU, tiFlashRU float64) string {
if (metrics == nil || metrics.IsZero()) && tiKVRU == 0 && tiFlashRU == 0 {
return ""
Expand Down
Loading