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 all commits
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
7 changes: 7 additions & 0 deletions pkg/executor/slow_query_sql_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -245,6 +245,10 @@ func TestSlowQuery(t *testing.T) {
f, err := os.CreateTemp("", "tidb-slow-*.log")
require.NoError(t, err)
_, err = f.WriteString(`
# Time: 2019-01-01T00:00:00+08:00
# Request_unit_v2: 123.45
# Request_unit_v2_detail: total_ru:123.45, tidb_ru:100.00, tikv_ru:20.00, tiflash_ru:3.45
select /* issue:67199 */ 1;
# Time: 2020-10-13T20:08:13.970563+08:00
# Plan_digest: 0368dd12858f813df842c17bcb37ca0e8858b554479bebcd78da1f8c14ad12d0
select * from t;
Expand Down Expand Up @@ -318,6 +322,9 @@ SELECT original_sql, bind_sql, default_db, status, create_time, update_time, cha

// issues 58194
tk.MustQuery("select max(Mem_arbitration) from `information_schema`.`slow_query`").Check(testkit.Rows("215"))
tk.MustQuery("select Request_unit_v2, Request_unit_v2 + 1, Request_unit_v2_detail from `information_schema`.`slow_query` " +
"where query = 'select /* issue:67199 */ 1;'").
Check(testkit.Rows("123.45 124.45 total_ru:123.45, tidb_ru:100.00, tikv_ru:20.00, tiflash_ru:3.45"))
}

func TestIssue37066(t *testing.T) {
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
14 changes: 10 additions & 4 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,12 @@ func (s *SessionVars) SlowLogFormat(logItems *SlowQueryLogItems) string {
tiKVRU = logItems.RUDetails.TiKVRUV2()
tiFlashRU = logItems.RUDetails.TiflashRU()
}
if formatted := execdetails.FormatRUV2Metrics(logItems.RUV2Metrics, s.RUV2Weights(), tiKVRU, tiFlashRU); len(formatted) > 0 {
writeSlowLogItem(&buf, SlowLogRUV2Metrics, formatted)
total, formatted := execdetails.FormatRUV2Summary(logItems.RUV2Metrics, s.RUV2Weights(), tiKVRU, tiFlashRU)
if len(total) > 0 {
writeSlowLogItem(&buf, SlowLogRequestUnitV2, total)
}
if len(formatted) > 0 {
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
5 changes: 4 additions & 1 deletion 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,11 @@ func TestFormatRUV2MetricsIncludesRUValuesFirst(t *testing.T) {
metrics.AddResultChunkCells(1000)
metrics.AddResourceManagerWriteCnt(20)
metrics.AddTiKVCoprocessorWorkTotal("BatchTopN", 10)
formatted := FormatRUV2Metrics(metrics, weights, 10987, 246)
total, formatted := FormatRUV2Summary(metrics, weights, 10987, 246)

require.Equal(t, "19983.42", total)
require.Equal(t, total, FormatRUV2Total(metrics, weights, 10987, 246))
require.Equal(t, formatted, FormatRUV2Metrics(metrics, weights, 10987, 246))
require.Contains(t, formatted, "tidb_ru:")
require.Contains(t, formatted, "tikv_ru:")
require.Contains(t, formatted, "tiflash_ru:")
Expand Down
49 changes: 41 additions & 8 deletions pkg/util/execdetails/ruv2_metrics.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -477,11 +477,8 @@ func sumRUV2LabelMap(values map[string]int64) int64 {
return total
}

// FormatRUV2Metrics formats RUv2 metrics into a compact string.
func FormatRUV2Metrics(metrics *RUV2Metrics, weights RUV2Weights, tiKVRU, tiFlashRU float64) string {
if (metrics == nil || metrics.IsZero()) && tiKVRU == 0 && tiFlashRU == 0 {
return ""
}
// FormatRUV2Summary formats the RUv2 total and detailed metrics in one pass.
func FormatRUV2Summary(metrics *RUV2Metrics, weights RUV2Weights, tiKVRU, tiFlashRU float64) (total string, detail string) {
var (
resultChunkCells int64
executorL1 map[string]int64
Expand All @@ -501,6 +498,7 @@ func FormatRUV2Metrics(metrics *RUV2Metrics, weights RUV2Weights, tiKVRU, tiFlas
tiKVStorageProcessedKeysBatchGet int64
tiKVStorageProcessedKeysGet int64
tiKVCoprocessorExecutorWorkTotal map[string]int64
tidbRU float64
)
if metrics != nil {
resultChunkCells = metrics.ResultChunkCells()
Expand All @@ -521,6 +519,29 @@ func FormatRUV2Metrics(metrics *RUV2Metrics, weights RUV2Weights, tiKVRU, tiFlas
tiKVStorageProcessedKeysBatchGet = metrics.TiKVStorageProcessedKeysBatchGet()
tiKVStorageProcessedKeysGet = metrics.TiKVStorageProcessedKeysGet()
tiKVCoprocessorExecutorWorkTotal = snapshotRUV2LabelCounter(&metrics.tikvCoprocessorWorkTotal)
tidbRU = metrics.calculateRUValuesWithWeights(weights)
}
if resultChunkCells == 0 &&
len(executorL1) == 0 &&
len(executorL2) == 0 &&
len(executorL3) == 0 &&
executorL5InsertRows == 0 &&
planCnt == 0 &&
planDeriveStatsPaths == 0 &&
sessionParserTotal == 0 &&
txnCnt == 0 &&
resourceManagerReadCnt == 0 &&
resourceManagerWriteCnt == 0 &&
tiKVKVEngineCacheMiss == 0 &&
tiKVCoprocessorExecutorIterations == 0 &&
tiKVCoprocessorResponseBytes == 0 &&
tiKVRaftstoreStoreWriteTriggerWB == 0 &&
tiKVStorageProcessedKeysBatchGet == 0 &&
tiKVStorageProcessedKeysGet == 0 &&
len(tiKVCoprocessorExecutorWorkTotal) == 0 &&
tiKVRU == 0 &&
tiFlashRU == 0 {
return "", ""
}
parts := make([]string, 0, 19)
appendInt := func(key string, value int64) {
Expand All @@ -541,8 +562,8 @@ func FormatRUV2Metrics(metrics *RUV2Metrics, weights RUV2Weights, tiKVRU, tiFlas
}
}

tidbRU := metrics.CalculateRUValues(weights)
totalRU := metrics.TotalRU(weights, tiKVRU, tiFlashRU)
totalRU := tidbRU + tiKVRU + tiFlashRU
total = fmt.Sprintf("%.2f", totalRU)
appendFloat64Always("total_ru", totalRU)
appendFloat64Always("tidb_ru", tidbRU)
appendFloat64Always("tikv_ru", tiKVRU)
Expand All @@ -567,7 +588,19 @@ func FormatRUV2Metrics(metrics *RUV2Metrics, weights RUV2Weights, tiKVRU, tiFlas
appendInt("tikv_storage_processed_keys_get", tiKVStorageProcessedKeysGet)
appendMap("tikv_coprocessor_executor_work_total", tiKVCoprocessorExecutorWorkTotal)

return strings.Join(parts, ", ")
return total, strings.Join(parts, ", ")
}

// FormatRUV2Total formats the RUv2 total into a slow log string.
func FormatRUV2Total(metrics *RUV2Metrics, weights RUV2Weights, tiKVRU, tiFlashRU float64) string {
total, _ := FormatRUV2Summary(metrics, weights, tiKVRU, tiFlashRU)
return total
}

// FormatRUV2Metrics formats RUv2 metrics into a compact detail string.
func FormatRUV2Metrics(metrics *RUV2Metrics, weights RUV2Weights, tiKVRU, tiFlashRU float64) string {
_, detail := FormatRUV2Summary(metrics, weights, tiKVRU, tiFlashRU)
return detail
}

func formatRUV2LabelMap(values map[string]int64) string {
Expand Down
Loading