diff --git a/DEPS.bzl b/DEPS.bzl index a5b5dddbd0fec..ed8ea0b2c45f8 100644 --- a/DEPS.bzl +++ b/DEPS.bzl @@ -7006,26 +7006,26 @@ def go_deps(): name = "com_github_tikv_client_go_v2", build_file_proto_mode = "disable_global", importpath = "github.com/tikv/client-go/v2", - sha256 = "c6c5bfe8a84d0b680266035d1ac87af6beca4cc552693d6753d4a9f18610c30d", - strip_prefix = "github.com/tikv/client-go/v2@v2.0.8-0.20231201024404-0ff16620f6c0", + sha256 = "04da7d520727a9140c0d472c0f0a054837aae1da3fa49101c0f52279c7d78094", + strip_prefix = "github.com/tikv/client-go/v2@v2.0.8-0.20231204074048-e80e9ca1fe66", urls = [ - "http://bazel-cache.pingcap.net:8080/gomod/github.com/tikv/client-go/v2/com_github_tikv_client_go_v2-v2.0.8-0.20231201024404-0ff16620f6c0.zip", - "http://ats.apps.svc/gomod/github.com/tikv/client-go/v2/com_github_tikv_client_go_v2-v2.0.8-0.20231201024404-0ff16620f6c0.zip", - "https://cache.hawkingrei.com/gomod/github.com/tikv/client-go/v2/com_github_tikv_client_go_v2-v2.0.8-0.20231201024404-0ff16620f6c0.zip", - "https://storage.googleapis.com/pingcapmirror/gomod/github.com/tikv/client-go/v2/com_github_tikv_client_go_v2-v2.0.8-0.20231201024404-0ff16620f6c0.zip", + "http://bazel-cache.pingcap.net:8080/gomod/github.com/tikv/client-go/v2/com_github_tikv_client_go_v2-v2.0.8-0.20231204074048-e80e9ca1fe66.zip", + "http://ats.apps.svc/gomod/github.com/tikv/client-go/v2/com_github_tikv_client_go_v2-v2.0.8-0.20231204074048-e80e9ca1fe66.zip", + "https://cache.hawkingrei.com/gomod/github.com/tikv/client-go/v2/com_github_tikv_client_go_v2-v2.0.8-0.20231204074048-e80e9ca1fe66.zip", + "https://storage.googleapis.com/pingcapmirror/gomod/github.com/tikv/client-go/v2/com_github_tikv_client_go_v2-v2.0.8-0.20231204074048-e80e9ca1fe66.zip", ], ) go_repository( name = "com_github_tikv_pd_client", build_file_proto_mode = "disable_global", importpath = "github.com/tikv/pd/client", - sha256 = "a6dcccfd436232d847d2ba2669d67d9708d7bc97f7571a4e57da18fdefeed852", - strip_prefix = "github.com/tikv/pd/client@v0.0.0-20231130081618-862eee18738e", + sha256 = "a1f7b29d753c60a373d29430d426be39a204fbedb62ceeb41296dee7bc6e5efe", + strip_prefix = "github.com/tikv/pd/client@v0.0.0-20231204034622-259435d93ae2", urls = [ - "http://bazel-cache.pingcap.net:8080/gomod/github.com/tikv/pd/client/com_github_tikv_pd_client-v0.0.0-20231130081618-862eee18738e.zip", - "http://ats.apps.svc/gomod/github.com/tikv/pd/client/com_github_tikv_pd_client-v0.0.0-20231130081618-862eee18738e.zip", - "https://cache.hawkingrei.com/gomod/github.com/tikv/pd/client/com_github_tikv_pd_client-v0.0.0-20231130081618-862eee18738e.zip", - "https://storage.googleapis.com/pingcapmirror/gomod/github.com/tikv/pd/client/com_github_tikv_pd_client-v0.0.0-20231130081618-862eee18738e.zip", + "http://bazel-cache.pingcap.net:8080/gomod/github.com/tikv/pd/client/com_github_tikv_pd_client-v0.0.0-20231204034622-259435d93ae2.zip", + "http://ats.apps.svc/gomod/github.com/tikv/pd/client/com_github_tikv_pd_client-v0.0.0-20231204034622-259435d93ae2.zip", + "https://cache.hawkingrei.com/gomod/github.com/tikv/pd/client/com_github_tikv_pd_client-v0.0.0-20231204034622-259435d93ae2.zip", + "https://storage.googleapis.com/pingcapmirror/gomod/github.com/tikv/pd/client/com_github_tikv_pd_client-v0.0.0-20231204034622-259435d93ae2.zip", ], ) go_repository( diff --git a/docs/design/2023-08-24-background-tasks-control.md b/docs/design/2023-08-24-background-tasks-control.md index b9d8d65cc48d8..2bee2437c8703 100644 --- a/docs/design/2023-08-24-background-tasks-control.md +++ b/docs/design/2023-08-24-background-tasks-control.md @@ -45,7 +45,7 @@ We also introduce a new session variable `tidb_request_source_type` to help tag SET @@tidb_request_source_type = "lightning"; ``` -The `tidb_request_source_type` variable is mostly used in the internal logic, but it's also possible to use this variable to allow other tasks be controlled as background jobs. For example, by setting this varialbe user can let `dumpling` or `TiSpark` tasks be control in the background mode. +The `tidb_request_source_type` variable is mostly used in the internal logic, but it's also possible to use this variable to allow other tasks be controlled as background jobs. For example, by setting this variable user can let `dumpling` or `TiSpark` tasks be control in the background mode. ## Implementation: Resource Limiter on TiKV for Background Task diff --git a/go.mod b/go.mod index 6d691268d9b95..88a45cc41fb34 100644 --- a/go.mod +++ b/go.mod @@ -102,8 +102,8 @@ require ( github.com/stretchr/testify v1.8.4 github.com/tdakkota/asciicheck v0.2.0 github.com/tiancaiamao/appdash v0.0.0-20181126055449-889f96f722a2 - github.com/tikv/client-go/v2 v2.0.8-0.20231201024404-0ff16620f6c0 - github.com/tikv/pd/client v0.0.0-20231130081618-862eee18738e + github.com/tikv/client-go/v2 v2.0.8-0.20231204074048-e80e9ca1fe66 + github.com/tikv/pd/client v0.0.0-20231204034622-259435d93ae2 github.com/timakin/bodyclose v0.0.0-20230421092635-574207250966 github.com/twmb/murmur3 v1.1.6 github.com/uber/jaeger-client-go v2.22.1+incompatible diff --git a/go.sum b/go.sum index 140ab0e9d35bf..b88dd815f4776 100644 --- a/go.sum +++ b/go.sum @@ -851,10 +851,10 @@ github.com/tiancaiamao/appdash v0.0.0-20181126055449-889f96f722a2 h1:mbAskLJ0oJf github.com/tiancaiamao/appdash v0.0.0-20181126055449-889f96f722a2/go.mod h1:2PfKggNGDuadAa0LElHrByyrz4JPZ9fFx6Gs7nx7ZZU= github.com/tiancaiamao/gp v0.0.0-20221230034425-4025bc8a4d4a h1:J/YdBZ46WKpXsxsW93SG+q0F8KI+yFrcIDT4c/RNoc4= github.com/tiancaiamao/gp v0.0.0-20221230034425-4025bc8a4d4a/go.mod h1:h4xBhSNtOeEosLJ4P7JyKXX7Cabg7AVkWCK5gV2vOrM= -github.com/tikv/client-go/v2 v2.0.8-0.20231201024404-0ff16620f6c0 h1:am8ME/PpDyhIM6oFg7QLq1FswcuL2DHi4PRBzkSDgGY= -github.com/tikv/client-go/v2 v2.0.8-0.20231201024404-0ff16620f6c0/go.mod h1:M+i6/DR7y1J7mG3SOdrmdkuLZe1gEqkdiV8J+mX1DiI= -github.com/tikv/pd/client v0.0.0-20231130081618-862eee18738e h1:11cWLLmEreKof/VJi6LLQ+Jkav5ZqPJgeI+KX4pc/DE= -github.com/tikv/pd/client v0.0.0-20231130081618-862eee18738e/go.mod h1:cd6zBqRM9aogxf26K8NnFRPVtq9BnRE59tKEpX8IaWQ= +github.com/tikv/client-go/v2 v2.0.8-0.20231204074048-e80e9ca1fe66 h1:+bCtNxUSYVmY/wmN8Zhf0UVl9mF+04/OjoseguM2aWY= +github.com/tikv/client-go/v2 v2.0.8-0.20231204074048-e80e9ca1fe66/go.mod h1:IE0/o4zWJW5Wpvp15CK2jpbu49DSLLSJBMNmwjv6I6o= +github.com/tikv/pd/client v0.0.0-20231204034622-259435d93ae2 h1:7fnKwFC9pgiOolvnUnquEAb60liIpna+0hFRkopaOSg= +github.com/tikv/pd/client v0.0.0-20231204034622-259435d93ae2/go.mod h1:cd6zBqRM9aogxf26K8NnFRPVtq9BnRE59tKEpX8IaWQ= github.com/timakin/bodyclose v0.0.0-20230421092635-574207250966 h1:quvGphlmUVU+nhpFa4gg4yJyTRJ13reZMDHrKwYw53M= github.com/timakin/bodyclose v0.0.0-20230421092635-574207250966/go.mod h1:27bSVNWSBOHm+qRp1T9qzaIpsWEP6TbUnei/43HK+PQ= github.com/tklauser/go-sysconf v0.3.9/go.mod h1:11DU/5sG7UexIrp/O6g35hrWzu0JxlwQ3LSFUzyeuhs= diff --git a/pkg/executor/adapter.go b/pkg/executor/adapter.go index 903883f6ac065..ca016b62ff273 100644 --- a/pkg/executor/adapter.go +++ b/pkg/executor/adapter.go @@ -1542,6 +1542,11 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool, hasMoreResults bool) { if tikvExecDetailRaw != nil { tikvExecDetail = *(tikvExecDetailRaw.(*util.ExecDetails)) } + ruDetails := util.NewRUDetails() + if ruDetailsVal := a.GoCtx.Value(util.RUDetailsCtxKey); ruDetailsVal != nil { + ruDetails = ruDetailsVal.(*util.RUDetails) + } + execDetail := stmtCtx.GetExecDetails() copTaskInfo := stmtCtx.CopTasksDetails() memMax := sessVars.MemTracker.MaxConsumed() @@ -1603,6 +1608,10 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool, hasMoreResults bool) { UsedStats: stmtCtx.GetUsedStatsInfo(false), IsSyncStatsFailed: stmtCtx.IsSyncStatsFailed, Warnings: collectWarningsForSlowLog(stmtCtx), + ResourceGroupName: sessVars.ResourceGroupName, + RRU: ruDetails.RRU(), + WRU: ruDetails.WRU(), + WaitRUDuration: ruDetails.RUWaitDuration(), } failpoint.Inject("assertSyncStatsFailed", func(val failpoint.Value) { if val.(bool) { diff --git a/pkg/executor/builder.go b/pkg/executor/builder.go index a305c56ae2990..7df7e756d3be1 100644 --- a/pkg/executor/builder.go +++ b/pkg/executor/builder.go @@ -84,7 +84,6 @@ import ( "github.com/tikv/client-go/v2/tikv" "github.com/tikv/client-go/v2/txnkv" "github.com/tikv/client-go/v2/txnkv/txnsnapshot" - clientutil "github.com/tikv/client-go/v2/util" ) // executorBuilder builds an Executor from a Plan. @@ -1318,22 +1317,6 @@ func (b *executorBuilder) buildExplain(v *plannercore.Explain) exec.Executor { if b.ctx.GetSessionVars().StmtCtx.RuntimeStatsColl == nil { b.ctx.GetSessionVars().StmtCtx.RuntimeStatsColl = execdetails.NewRuntimeStatsColl(nil) } - // If the resource group name is not empty, we could collect and display the RU - // runtime stats for analyze executor. - resourceGroupName := b.ctx.GetSessionVars().ResourceGroupName - // Try to register the RU runtime stats for analyze executor. - if store, ok := b.ctx.GetStore().(interface { - CreateRURuntimeStats(uint64) *clientutil.RURuntimeStats - }); len(resourceGroupName) > 0 && ok { - // StartTS will be used to identify this SQL, so that the runtime stats could - // aggregate the RU stats beneath the KV storage client. - startTS, err := b.getSnapshotTS() - if err != nil { - b.err = err - return nil - } - explainExec.ruRuntimeStats = store.CreateRURuntimeStats(startTS) - } explainExec.analyzeExec = b.build(v.TargetPlan) } return explainExec diff --git a/pkg/executor/explain.go b/pkg/executor/explain.go index ea635b5d0d090..0c251624006b3 100644 --- a/pkg/executor/explain.go +++ b/pkg/executor/explain.go @@ -44,12 +44,11 @@ import ( type ExplainExec struct { exec.BaseExecutor - explain *core.Explain - analyzeExec exec.Executor - executed bool - ruRuntimeStats *clientutil.RURuntimeStats - rows [][]string - cursor int + explain *core.Explain + analyzeExec exec.Executor + executed bool + rows [][]string + cursor int } // Open implements the Executor Open interface. @@ -136,8 +135,10 @@ func (e *ExplainExec) executeAnalyzeExec(ctx context.Context) (err error) { } // Register the RU runtime stats to the runtime stats collection after the analyze executor has been executed. if e.analyzeExec != nil && e.executed { - if coll := e.Ctx().GetSessionVars().StmtCtx.RuntimeStatsColl; coll != nil { - coll.RegisterStats(e.explain.TargetPlan.ID(), &ruRuntimeStats{e.ruRuntimeStats}) + ruDetailsRaw := ctx.Value(clientutil.RUDetailsCtxKey) + if coll := e.Ctx().GetSessionVars().StmtCtx.RuntimeStatsColl; coll != nil && ruDetailsRaw != nil { + ruDetails := ruDetailsRaw.(*clientutil.RUDetails) + coll.RegisterStats(e.explain.TargetPlan.ID(), &ruRuntimeStats{ruDetails}) } } return err @@ -316,41 +317,33 @@ func getHeapProfile() (fileName string, err error) { return fileName, nil } -// ruRuntimeStats is a wrapper of clientutil.RURuntimeStats, +// ruRuntimeStats is a wrapper of clientutil.RUDetails, // which implements the RuntimeStats interface. type ruRuntimeStats struct { - *clientutil.RURuntimeStats + *clientutil.RUDetails } // String implements the RuntimeStats interface. func (e *ruRuntimeStats) String() string { - if e.RURuntimeStats != nil { - return fmt.Sprintf("RU:%f", e.RURuntimeStats.RRU()+e.RURuntimeStats.WRU()) + if e.RUDetails != nil { + return fmt.Sprintf("RU:%f", e.RRU()+e.WRU()) } return "" } // Clone implements the RuntimeStats interface. func (e *ruRuntimeStats) Clone() execdetails.RuntimeStats { - newRs := &ruRuntimeStats{} - if e.RURuntimeStats != nil { - newRs.RURuntimeStats = e.RURuntimeStats.Clone() - } - return newRs + return &ruRuntimeStats{RUDetails: e.RUDetails.Clone()} } // Merge implements the RuntimeStats interface. func (e *ruRuntimeStats) Merge(other execdetails.RuntimeStats) { - tmp, ok := other.(*ruRuntimeStats) - if !ok { - return - } - if tmp.RURuntimeStats != nil { - if e.RURuntimeStats == nil { - e.RURuntimeStats = tmp.RURuntimeStats.Clone() - return + if tmp, ok := other.(*ruRuntimeStats); ok { + if e.RUDetails != nil { + e.RUDetails.Merge(tmp.RUDetails) + } else { + e.RUDetails = tmp.RUDetails.Clone() } - e.RURuntimeStats.Merge(tmp.RURuntimeStats) } } diff --git a/pkg/executor/slow_query.go b/pkg/executor/slow_query.go index 43416a23cea8d..e32cf6bb6e996 100644 --- a/pkg/executor/slow_query.go +++ b/pkg/executor/slow_query.go @@ -749,7 +749,8 @@ func getColumnValueFactoryByName(colName string, columnIdx int) (slowQueryColumn execdetails.CopTimeStr, execdetails.ProcessTimeStr, execdetails.WaitTimeStr, execdetails.BackoffTimeStr, execdetails.LockKeysTimeStr, variable.SlowLogCopProcAvg, variable.SlowLogCopProcP90, variable.SlowLogCopProcMax, variable.SlowLogCopWaitAvg, variable.SlowLogCopWaitP90, variable.SlowLogCopWaitMax, variable.SlowLogKVTotal, - variable.SlowLogPDTotal, variable.SlowLogBackoffTotal, variable.SlowLogWriteSQLRespTotal: + variable.SlowLogPDTotal, variable.SlowLogBackoffTotal, variable.SlowLogWriteSQLRespTotal, variable.SlowLogRRU, + variable.SlowLogWRU, variable.SlowLogWaitRUDuration: return func(row []types.Datum, value string, tz *time.Location, checker *slowLogChecker) (valid bool, err error) { v, err := strconv.ParseFloat(value, 64) if err != nil { @@ -760,7 +761,8 @@ func getColumnValueFactoryByName(colName string, columnIdx int) (slowQueryColumn }, nil 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.SlowLogPrevStmt, variable.SlowLogQuerySQLStr, variable.SlowLogWarnings, variable.SlowLogSessAliasStr, + variable.SlowLogResourceGroup: return func(row []types.Datum, value string, tz *time.Location, checker *slowLogChecker) (valid bool, err error) { row[columnIdx] = types.NewStringDatum(value) return true, nil diff --git a/pkg/executor/slow_query_test.go b/pkg/executor/slow_query_test.go index fa15d46b59689..8d6a1d19f17ec 100644 --- a/pkg/executor/slow_query_test.go +++ b/pkg/executor/slow_query_test.go @@ -138,6 +138,10 @@ func TestParseSlowLogFile(t *testing.T) { # Plan_from_binding: true # Succ: false # IsExplicitTxn: true +# Resource_group: default +# Request_unit_read: 2.158 +# Request_unit_write: 2.123 +# Time_queued_by_rc: 0.05 # Plan_digest: 60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4 # Prev_stmt: update t set i = 1; use test; @@ -164,7 +168,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,65536,0,0,0,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,,60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4,` + + `0,0,1,0,1,1,0,default,2.158,2.123,0.05,,60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4,` + `,update t set i = 1;,select * from t;` require.Equal(t, expectRecordString, recordString) @@ -187,7 +191,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,65536,0,0,0,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,,60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4,` + + `0,0,1,0,1,1,0,default,2.158,2.123,0.05,,60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4,` + `,update t set i = 1;,select * from t;` require.Equal(t, expectRecordString, recordString) diff --git a/pkg/infoschema/internal/testkit.go b/pkg/infoschema/internal/testkit.go index 2afe472f98455..50eb91f7ac45a 100644 --- a/pkg/infoschema/internal/testkit.go +++ b/pkg/infoschema/internal/testkit.go @@ -55,6 +55,7 @@ func PrepareSlowLogfile(t *testing.T, slowLogFileName string) { # Plan: abcd # Plan_digest: 60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4 # Prev_stmt: update t set i = 2; +# Resource_group: default select * from t_slim; # Time: 2021-09-08T14:39:54.506967433+08:00 # Txn_start_ts: 427578666238083075 @@ -82,6 +83,9 @@ select * from t_slim; # Backoff_total: 100.054 # Write_sql_response_total: 0 # Succ: true +# Resource_group: rg1 +# Request_unit_read: 96.66703066666668 +# Request_unit_write: 3182.424414062492 INSERT INTO ...; `) require.NoError(t, f.Close()) diff --git a/pkg/infoschema/tables.go b/pkg/infoschema/tables.go index c4fb011ad9fcf..e616c56250e91 100644 --- a/pkg/infoschema/tables.go +++ b/pkg/infoschema/tables.go @@ -930,6 +930,10 @@ var slowQueryCols = []columnInfo{ {name: variable.SlowLogPlanFromCache, tp: mysql.TypeTiny, size: 1}, {name: variable.SlowLogPlanFromBinding, tp: mysql.TypeTiny, size: 1}, {name: variable.SlowLogHasMoreResults, tp: mysql.TypeTiny, size: 1}, + {name: variable.SlowLogResourceGroup, tp: mysql.TypeVarchar, size: 64}, + {name: variable.SlowLogRRU, tp: mysql.TypeDouble, size: 22}, + {name: variable.SlowLogWRU, tp: mysql.TypeDouble, size: 22}, + {name: variable.SlowLogWaitRUDuration, tp: mysql.TypeDouble, size: 22}, {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}, diff --git a/pkg/infoschema/test/clustertablestest/tables_test.go b/pkg/infoschema/test/clustertablestest/tables_test.go index 4f646173e65be..9074461649cc7 100644 --- a/pkg/infoschema/test/clustertablestest/tables_test.go +++ b/pkg/infoschema/test/clustertablestest/tables_test.go @@ -431,11 +431,16 @@ func TestSlowQuery(t *testing.T) { "1", "0", "0", + "default", + "0", + "0", + "0", "abcd", "60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4", "", "update t set i = 2;", - "select * from t_slim;"}, + "select * from t_slim;", + }, {"2021-09-08 14:39:54.506967", "427578666238083075", "root", @@ -506,6 +511,10 @@ func TestSlowQuery(t *testing.T) { "0", "0", "0", + "rg1", + "96.66703066666668", + "3182.424414062492", + "0", "", "", "", diff --git a/pkg/server/conn.go b/pkg/server/conn.go index 7d6d12d4190e1..8d97d23382303 100644 --- a/pkg/server/conn.go +++ b/pkg/server/conn.go @@ -2028,6 +2028,7 @@ func (cc *clientConn) prefetchPointPlanKeys(ctx context.Context, stmts []ast.Stm func (cc *clientConn) handleStmt(ctx context.Context, stmt ast.StmtNode, warns []stmtctx.SQLWarn, lastStmt bool) (bool, error) { ctx = context.WithValue(ctx, execdetails.StmtExecDetailKey, &execdetails.StmtExecDetails{}) ctx = context.WithValue(ctx, util.ExecDetailsKey, &util.ExecDetails{}) + ctx = context.WithValue(ctx, util.RUDetailsCtxKey, util.NewRUDetails()) reg := trace.StartRegion(ctx, "ExecuteStmt") cc.audit(plugin.Starting) rs, err := cc.ctx.ExecuteStmt(ctx, stmt) diff --git a/pkg/server/conn_stmt.go b/pkg/server/conn_stmt.go index cfb6a20da506f..f528477c6d5bd 100644 --- a/pkg/server/conn_stmt.go +++ b/pkg/server/conn_stmt.go @@ -230,6 +230,7 @@ func (cc *clientConn) handleStmtExecute(ctx context.Context, data []byte) (err e func (cc *clientConn) executePlanCacheStmt(ctx context.Context, stmt interface{}, args []param.BinaryParam, useCursor bool) (err error) { ctx = context.WithValue(ctx, execdetails.StmtExecDetailKey, &execdetails.StmtExecDetails{}) ctx = context.WithValue(ctx, util.ExecDetailsKey, &util.ExecDetails{}) + ctx = context.WithValue(ctx, util.RUDetailsCtxKey, util.NewRUDetails()) retryable, err := cc.executePreparedStmtAndWriteResult(ctx, stmt.(PreparedStatement), args, useCursor) if err != nil { action, txnErr := sessiontxn.GetTxnManager(&cc.ctx).OnStmtErrorForNextAction(ctx, sessiontxn.StmtErrAfterQuery, err) diff --git a/pkg/session/session.go b/pkg/session/session.go index 5fcac90030187..1c33aa37b1c49 100644 --- a/pkg/session/session.go +++ b/pkg/session/session.go @@ -1862,6 +1862,7 @@ func (s *session) ExecRestrictedStmt(ctx context.Context, stmtNode ast.StmtNode, metrics.SessionRestrictedSQLCounter.Inc() ctx = context.WithValue(ctx, execdetails.StmtExecDetailKey, &execdetails.StmtExecDetails{}) ctx = context.WithValue(ctx, tikvutil.ExecDetailsKey, &tikvutil.ExecDetails{}) + ctx = context.WithValue(ctx, tikvutil.RUDetailsCtxKey, tikvutil.NewRUDetails()) rs, err := se.ExecuteStmt(ctx, stmtNode) if err != nil { se.sessionVars.StmtCtx.AppendError(err) diff --git a/pkg/sessionctx/variable/session.go b/pkg/sessionctx/variable/session.go index eac7ef14c9f9b..ff69ff2a6eefc 100644 --- a/pkg/sessionctx/variable/session.go +++ b/pkg/sessionctx/variable/session.go @@ -3113,6 +3113,14 @@ const ( SlowLogIsWriteCacheTable = "IsWriteCacheTable" // SlowLogIsSyncStatsFailed is used to indicate whether any failure happen during sync stats SlowLogIsSyncStatsFailed = "IsSyncStatsFailed" + // SlowLogResourceGroup is the resource group name that the current session bind. + SlowLogResourceGroup = "Resource_group" + // SlowLogRRU is the read request_unit(RU) cost + SlowLogRRU = "Request_unit_read" + // SlowLogWRU is the write request_unit(RU) cost + SlowLogWRU = "Request_unit_write" + // SlowLogWaitRUDuration is the total duration for kv requests to wait available request-units. + SlowLogWaitRUDuration = "Time_queued_by_rc" ) // GenerateBinaryPlan decides whether we should record binary plan in slow log and stmt summary. @@ -3168,6 +3176,10 @@ type SlowQueryLogItems struct { UsedStats map[int64]*stmtctx.UsedStatsInfoForTable IsSyncStatsFailed bool Warnings []JSONSQLWarnForSlowLog + ResourceGroupName string + RRU float64 + WRU float64 + WaitRUDuration time.Duration } // SlowLogFormat uses for formatting slow log. @@ -3365,6 +3377,20 @@ func (s *SessionVars) SlowLogFormat(logItems *SlowQueryLogItems) string { if len(logItems.BinaryPlan) != 0 { writeSlowLogItem(&buf, SlowLogBinaryPlan, logItems.BinaryPlan) } + + if logItems.ResourceGroupName != "" { + writeSlowLogItem(&buf, SlowLogResourceGroup, logItems.ResourceGroupName) + } + if logItems.RRU > 0.0 { + writeSlowLogItem(&buf, SlowLogRRU, strconv.FormatFloat(logItems.RRU, 'f', -1, 64)) + } + if logItems.WRU > 0.0 { + writeSlowLogItem(&buf, SlowLogWRU, strconv.FormatFloat(logItems.WRU, 'f', -1, 64)) + } + if logItems.WaitRUDuration > time.Duration(0) { + writeSlowLogItem(&buf, SlowLogWaitRUDuration, strconv.FormatFloat(logItems.WaitRUDuration.Seconds(), 'f', -1, 64)) + } + if logItems.PrevStmt != "" { writeSlowLogItem(&buf, SlowLogPrevStmt, logItems.PrevStmt) } diff --git a/pkg/sessionctx/variable/session_test.go b/pkg/sessionctx/variable/session_test.go index b45046836d8fe..f7e0abf6a9dc9 100644 --- a/pkg/sessionctx/variable/session_test.go +++ b/pkg/sessionctx/variable/session_test.go @@ -258,7 +258,11 @@ func TestSlowLogFormat(t *testing.T) { # Succ: true # IsExplicitTxn: true # IsSyncStatsFailed: false -# IsWriteCacheTable: true` +# IsWriteCacheTable: true +# Resource_group: rg1 +# Request_unit_read: 50 +# Request_unit_write: 100.56 +# Time_queued_by_rc: 0.134` sql := "select * from t;" _, digest := parser.NormalizeDigest(sql) logItems := &variable.SlowQueryLogItems{ @@ -297,6 +301,10 @@ func TestSlowLogFormat(t *testing.T) { IsExplicitTxn: true, IsWriteCacheTable: true, UsedStats: map[int64]*stmtctx.UsedStatsInfoForTable{1: usedStats1, 2: usedStats2}, + ResourceGroupName: "rg1", + RRU: 50.0, + WRU: 100.56, + WaitRUDuration: 134 * time.Millisecond, } logString := seVar.SlowLogFormat(logItems) require.Equal(t, resultFields+"\n"+sql, logString)