From b4a73d5e6ddaca43612d444dba45f66c989cb05f Mon Sep 17 00:00:00 2001 From: Ti Chi Robot Date: Sun, 18 Feb 2024 19:36:25 +0800 Subject: [PATCH] executor: add ru details in slow log and INFORMATION_SCHEMA.SLOW_QUERY (#49067) (#50881) close pingcap/tidb#42892, ref pingcap/tidb#49318 --- DEPS.bzl | 24 +++++----- .../2023-08-24-background-tasks-control.md | 2 +- go.mod | 4 +- go.sum | 8 ++-- pkg/executor/adapter.go | 9 ++++ pkg/executor/builder.go | 17 ------- pkg/executor/explain.go | 45 ++++++++----------- pkg/executor/slow_query.go | 6 ++- pkg/executor/slow_query_test.go | 8 +++- pkg/infoschema/internal/testkit.go | 4 ++ pkg/infoschema/tables.go | 4 ++ .../test/clustertablestest/tables_test.go | 11 ++++- pkg/server/conn.go | 1 + pkg/server/conn_stmt.go | 1 + pkg/session/session.go | 1 + pkg/sessionctx/variable/session.go | 26 +++++++++++ pkg/sessionctx/variable/session_test.go | 10 ++++- 17 files changed, 113 insertions(+), 68 deletions(-) diff --git a/DEPS.bzl b/DEPS.bzl index e40e888990516..f0dc008459ccb 100644 --- a/DEPS.bzl +++ b/DEPS.bzl @@ -7028,26 +7028,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 = "3158bbaec8eddd06a428bbb014a0c37557c134078d7de095634609f9cc87e879", - strip_prefix = "github.com/tikv/client-go/v2@v2.0.8-0.20231116065855-46811b6ac353", + sha256 = "013685f8bba022b46ff651baad20811d77fdf8d3c625d36e5860e74f9efb6e89", + strip_prefix = "github.com/tikv/client-go/v2@v2.0.8-0.20240218024828-b13f4be4e6f9", urls = [ - "http://bazel-cache.pingcap.net:8080/gomod/github.com/tikv/client-go/v2/com_github_tikv_client_go_v2-v2.0.8-0.20231116065855-46811b6ac353.zip", - "http://ats.apps.svc/gomod/github.com/tikv/client-go/v2/com_github_tikv_client_go_v2-v2.0.8-0.20231116065855-46811b6ac353.zip", - "https://cache.hawkingrei.com/gomod/github.com/tikv/client-go/v2/com_github_tikv_client_go_v2-v2.0.8-0.20231116065855-46811b6ac353.zip", - "https://storage.googleapis.com/pingcapmirror/gomod/github.com/tikv/client-go/v2/com_github_tikv_client_go_v2-v2.0.8-0.20231116065855-46811b6ac353.zip", + "http://bazel-cache.pingcap.net:8080/gomod/github.com/tikv/client-go/v2/com_github_tikv_client_go_v2-v2.0.8-0.20240218024828-b13f4be4e6f9.zip", + "http://ats.apps.svc/gomod/github.com/tikv/client-go/v2/com_github_tikv_client_go_v2-v2.0.8-0.20240218024828-b13f4be4e6f9.zip", + "https://cache.hawkingrei.com/gomod/github.com/tikv/client-go/v2/com_github_tikv_client_go_v2-v2.0.8-0.20240218024828-b13f4be4e6f9.zip", + "https://storage.googleapis.com/pingcapmirror/gomod/github.com/tikv/client-go/v2/com_github_tikv_client_go_v2-v2.0.8-0.20240218024828-b13f4be4e6f9.zip", ], ) go_repository( name = "com_github_tikv_pd_client", build_file_proto_mode = "disable_global", importpath = "github.com/tikv/pd/client", - sha256 = "fc6b1ce304af19928623f951c23ce58734ce0efb7a36ef621d05be893a94f869", - strip_prefix = "github.com/tikv/pd/client@v0.0.0-20240102100501-7ce5860ab342", + sha256 = "14edd15ac295a7c88e93fc86e039c5649f877efc87f294c1cc523a2879f2da77", + strip_prefix = "github.com/tikv/pd/client@v0.0.0-20240210135946-3488a653ddd9", urls = [ - "http://bazel-cache.pingcap.net:8080/gomod/github.com/tikv/pd/client/com_github_tikv_pd_client-v0.0.0-20240102100501-7ce5860ab342.zip", - "http://ats.apps.svc/gomod/github.com/tikv/pd/client/com_github_tikv_pd_client-v0.0.0-20240102100501-7ce5860ab342.zip", - "https://cache.hawkingrei.com/gomod/github.com/tikv/pd/client/com_github_tikv_pd_client-v0.0.0-20240102100501-7ce5860ab342.zip", - "https://storage.googleapis.com/pingcapmirror/gomod/github.com/tikv/pd/client/com_github_tikv_pd_client-v0.0.0-20240102100501-7ce5860ab342.zip", + "http://bazel-cache.pingcap.net:8080/gomod/github.com/tikv/pd/client/com_github_tikv_pd_client-v0.0.0-20240210135946-3488a653ddd9.zip", + "http://ats.apps.svc/gomod/github.com/tikv/pd/client/com_github_tikv_pd_client-v0.0.0-20240210135946-3488a653ddd9.zip", + "https://cache.hawkingrei.com/gomod/github.com/tikv/pd/client/com_github_tikv_pd_client-v0.0.0-20240210135946-3488a653ddd9.zip", + "https://storage.googleapis.com/pingcapmirror/gomod/github.com/tikv/pd/client/com_github_tikv_pd_client-v0.0.0-20240210135946-3488a653ddd9.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 0d395f4d87b33..fa9f5d8b2da27 100644 --- a/go.mod +++ b/go.mod @@ -104,8 +104,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.20231116065855-46811b6ac353 - github.com/tikv/pd/client v0.0.0-20240102100501-7ce5860ab342 + github.com/tikv/client-go/v2 v2.0.8-0.20240218024828-b13f4be4e6f9 + github.com/tikv/pd/client v0.0.0-20240210135946-3488a653ddd9 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 10a24117d0869..f117aec4ef2e0 100644 --- a/go.sum +++ b/go.sum @@ -995,10 +995,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.20231116065855-46811b6ac353 h1:3yZMlIPxpFEepJOJVq64e/ulhyON3cOoRynYGEOGBP8= -github.com/tikv/client-go/v2 v2.0.8-0.20231116065855-46811b6ac353/go.mod h1:0W23EJEJejgM/75ZhMaRLokR/OMlGymyGrB2/gvfuvs= -github.com/tikv/pd/client v0.0.0-20240102100501-7ce5860ab342 h1:MHYipM+19XLf/QPM8xsjDW3+p2/aOnBqPh+GnO9LDd8= -github.com/tikv/pd/client v0.0.0-20240102100501-7ce5860ab342/go.mod h1:AwjTSpM7CgAynYwB6qTG5R5fVC9/eXlQXiTO6zDL1HI= +github.com/tikv/client-go/v2 v2.0.8-0.20240218024828-b13f4be4e6f9 h1:6HtoVi0L3bFqv0fMrOf2HcpyJ73To6hi/BLPwsaXHUk= +github.com/tikv/client-go/v2 v2.0.8-0.20240218024828-b13f4be4e6f9/go.mod h1:37p0ryKaieJbBpVDWnaPi2ZS6UFqkgpsemBLkGX2FvM= +github.com/tikv/pd/client v0.0.0-20240210135946-3488a653ddd9 h1:tNpO/lF/kAzl3g7JQScGi+iWSWKtPPr/YXhxYNPWsHM= +github.com/tikv/pd/client v0.0.0-20240210135946-3488a653ddd9/go.mod h1:AwjTSpM7CgAynYwB6qTG5R5fVC9/eXlQXiTO6zDL1HI= 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 100cb2cffaf57..3e28779a2466b 100644 --- a/pkg/executor/adapter.go +++ b/pkg/executor/adapter.go @@ -1539,6 +1539,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() @@ -1600,6 +1605,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 7870c2ded5dcb..078a90fdc174f 100644 --- a/pkg/executor/builder.go +++ b/pkg/executor/builder.go @@ -83,7 +83,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. @@ -1316,22 +1315,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 0946874bd0773..99413392848d3 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 @@ -317,41 +318,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 7034d4511feef..2dd5ecb1b0dbf 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 0c90cefc54872..f9088f34b6a68 100644 --- a/pkg/infoschema/tables.go +++ b/pkg/infoschema/tables.go @@ -924,6 +924,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 ddcf6c69a6b88..554f83f314f34 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 e1d07febcc32e..bbacc7cc5ad72 100644 --- a/pkg/server/conn.go +++ b/pkg/server/conn.go @@ -2031,6 +2031,7 @@ func setResourceGroupTaggerForMultiStmtPrefetch(snapshot kv.Snapshot, sqls strin 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 93e7e1511f4d1..3e75cba23255a 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 []expression.Expression, 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 933f9420ddd8a..4e04fa608ad9f 100644 --- a/pkg/session/session.go +++ b/pkg/session/session.go @@ -1920,6 +1920,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 31b887c18af88..360a6fe28a8e4 100644 --- a/pkg/sessionctx/variable/session.go +++ b/pkg/sessionctx/variable/session.go @@ -3088,6 +3088,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. @@ -3143,6 +3151,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. @@ -3340,6 +3352,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)