Skip to content
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.

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

executor: add ru details in slow log and INFORMATION_SCHEMA.SLOW_QUERY #49067

Merged
merged 10 commits into from
Dec 13, 2023
Merged
Show file tree
Hide file tree
Changes from 1 commit
Commits
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
2 changes: 1 addition & 1 deletion br/pkg/pdutil/pd.go
Original file line number Diff line number Diff line change
Expand Up @@ -389,7 +389,7 @@ func (p *PdController) getRegionCountWith(
}
var err error
for _, addr := range p.getAllPDAddrs() {
v, e := get(ctx, addr, pdhttp.RegionStatsByKeyRange(pdhttp.NewKeyRange(start, end)), p.cli, http.MethodGet, nil)
v, e := get(ctx, addr, pdhttp.RegionStatsByKeyRange(pdhttp.NewKeyRange(start, end), false), p.cli, http.MethodGet, nil)
if e != nil {
err = e
continue
Expand Down
2 changes: 1 addition & 1 deletion docs/design/2023-08-24-background-tasks-control.md
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down
2 changes: 2 additions & 0 deletions go.mod
Original file line number Diff line number Diff line change
Expand Up @@ -312,4 +312,6 @@ replace (
github.com/dgrijalva/jwt-go => github.com/form3tech-oss/jwt-go v3.2.6-0.20210809144907-32ab6a8243d7+incompatible
github.com/go-ldap/ldap/v3 => github.com/YangKeao/ldap/v3 v3.4.5-0.20230421065457-369a3bab1117
github.com/pingcap/tidb/pkg/parser => ./pkg/parser
github.com/tikv/client-go/v2 => github.com/glorv/client-go/v2 v2.0.1-0.20231130110809-812d6876b43f
github.com/tikv/pd/client => github.com/glorv/pd/client v0.0.0-20231130110105-b19ebbf2cee3
)
8 changes: 4 additions & 4 deletions go.sum
Original file line number Diff line number Diff line change
Expand Up @@ -271,6 +271,10 @@ github.com/ghemawat/stream v0.0.0-20171120220530-696b145b53b9/go.mod h1:106OIgoo
github.com/ghodss/yaml v1.0.0/go.mod h1:4dBDuWmgqj2HViK6kFavaiC9ZROes6MMH2rRYeMEF04=
github.com/gin-contrib/sse v0.0.0-20190301062529-5545eab6dad3/go.mod h1:VJ0WA2NBN22VlZ2dKZQPAPnyWw5XTlK1KymzLKsr59s=
github.com/gin-gonic/gin v1.4.0/go.mod h1:OW2EZn3DO8Ln9oIKOvM++LBO+5UPHJJDH72/q/3rZdM=
github.com/glorv/client-go/v2 v2.0.1-0.20231130110809-812d6876b43f h1:pMnYb5jUkLB9QqXxitBtcg/8Hne+5oYTW9P9w3UN2Jo=
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please run make bazel_prepare and upload the dependencies.

github.com/glorv/client-go/v2 v2.0.1-0.20231130110809-812d6876b43f/go.mod h1:5ixpwHJTTgiIBBLMgxqh6GB2QdizcLbmRIpst5DkyA8=
github.com/glorv/pd/client v0.0.0-20231130110105-b19ebbf2cee3 h1:tABqnHuWoSZVB3dIGU3QIxWGnQLc9BlLfjOZPUWgaII=
github.com/glorv/pd/client v0.0.0-20231130110105-b19ebbf2cee3/go.mod h1:cd6zBqRM9aogxf26K8NnFRPVtq9BnRE59tKEpX8IaWQ=
github.com/go-asn1-ber/asn1-ber v1.5.4 h1:vXT6d/FNDiELJnLb6hGNa309LMsrCoYFvpwHDF0+Y1A=
github.com/go-asn1-ber/asn1-ber v1.5.4/go.mod h1:hEBeB/ic+5LoWskz+yKT7vGhhPYkProFKoKdwZRWMe0=
github.com/go-check/check v0.0.0-20180628173108-788fd7840127/go.mod h1:9ES+weclKsC9YodN5RgxqK/VD9HM9JsCSh7rNhMZE98=
Expand Down Expand Up @@ -851,10 +855,6 @@ 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.20231116051730-1c2351c28173 h1:lmJzX0kqrV7kO21wrZPbtjkidzwbDCfXeQrhDWEi5dE=
github.com/tikv/client-go/v2 v2.0.8-0.20231116051730-1c2351c28173/go.mod h1:BOGTSZtbMHEnGC4HOpbONdnTQF+E9nb2Io7c3P9sb7g=
github.com/tikv/pd/client v0.0.0-20231127075044-9f4803d8bd05 h1:87NPUfzaVrO5MTBwVCPQ/FlJGpFnHi6WFYHDYD3n3Zc=
github.com/tikv/pd/client v0.0.0-20231127075044-9f4803d8bd05/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=
Expand Down
2 changes: 1 addition & 1 deletion pkg/domain/infosync/tiflash_manager.go
Original file line number Diff line number Diff line change
Expand Up @@ -495,7 +495,7 @@ func (m *TiFlashReplicaManagerCtx) GetRegionCountFromPD(ctx context.Context, tab
endKey := tablecodec.EncodeTablePrefix(tableID + 1)
startKey, endKey = m.codec.EncodeRegionRange(startKey, endKey)

p := fmt.Sprintf("%s&count", pd.RegionStatsByKeyRange(pd.NewKeyRange(startKey, endKey)))
p := fmt.Sprintf("%s&count", pd.RegionStatsByKeyRange(pd.NewKeyRange(startKey, endKey), false))
res, err := doRequest(ctx, "GetPDRegionStats", m.etcdCli.Endpoints(), p, "GET", nil)
if err != nil {
return errors.Trace(err)
Expand Down
4 changes: 4 additions & 0 deletions pkg/executor/adapter.go
Original file line number Diff line number Diff line change
Expand Up @@ -1603,6 +1603,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: float64(atomic.LoadInt64(&tikvExecDetail.MilliRRU)) / 1000.0,
WRU: float64(atomic.LoadInt64(&tikvExecDetail.MilliWRU)) / 1000.0,
WaitRUDuration: time.Duration(atomic.LoadInt64(&tikvExecDetail.WaitRUDuration)),
}
failpoint.Inject("assertSyncStatsFailed", func(val failpoint.Value) {
if val.(bool) {
Expand Down
6 changes: 4 additions & 2 deletions pkg/executor/slow_query.go
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand All @@ -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
Expand Down
8 changes: 6 additions & 2 deletions pkg/executor/slow_query_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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.158
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
# Request_unit_write: 2.158
# Request_unit_write: 2.159

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

use distinct value too.

# Time_queued_by_rc: 0.05
# Plan_digest: 60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4
# Prev_stmt: update t set i = 1;
use test;
Expand Down Expand Up @@ -165,7 +169,7 @@ select * from t;`
`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,` +
`,update t set i = 1;,select * from t;`
`,update t set i = 1;,select * from t;,default,2.158,2.158,0.05`
require.Equal(t, expectRecordString, recordString)

// Issue 20928
Expand All @@ -188,7 +192,7 @@ select * from t;`
`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,` +
`,update t set i = 1;,select * from t;`
`,update t set i = 1;,select * from t;,default,2.158,2.158,0.05`
require.Equal(t, expectRecordString, recordString)

// fix sql contain '# ' bug
Expand Down
4 changes: 4 additions & 0 deletions pkg/infoschema/tables.go
Original file line number Diff line number Diff line change
Expand Up @@ -932,6 +932,10 @@ var slowQueryCols = []columnInfo{
{name: variable.SlowLogBinaryPlan, tp: mysql.TypeLongBlob, size: types.UnspecifiedLength},
{name: variable.SlowLogPrevStmt, tp: mysql.TypeLongBlob, size: types.UnspecifiedLength},
{name: variable.SlowLogQuerySQLStr, tp: mysql.TypeLongBlob, size: types.UnspecifiedLength},
{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},
}

// TableTiDBHotRegionsCols is TiDB hot region mem table columns.
Expand Down
26 changes: 26 additions & 0 deletions pkg/sessionctx/variable/session.go
Original file line number Diff line number Diff line change
Expand Up @@ -3096,6 +3096,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"
// SlowLogRRU 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"
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

maybe we need to add tikv side wait duration in the future.

)

// GenerateBinaryPlan decides whether we should record binary plan in slow log and stmt summary.
Expand Down Expand Up @@ -3151,6 +3159,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.
Expand Down Expand Up @@ -3348,6 +3360,20 @@ func (s *SessionVars) SlowLogFormat(logItems *SlowQueryLogItems) string {
if len(logItems.BinaryPlan) != 0 {
writeSlowLogItem(&buf, SlowLogBinaryPlan, logItems.BinaryPlan)
}

if s.ResourceGroupName != "" {
writeSlowLogItem(&buf, SlowLogResourceGroup, logItems.ResourceGroupName)
}
if logItems.WaitRUDuration > time.Duration(0) {
writeSlowLogItem(&buf, SlowLogWaitRUDuration, strconv.FormatFloat(logItems.KVTotal.Seconds(), 'f', -1, 64))
}
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.PrevStmt != "" {
writeSlowLogItem(&buf, SlowLogPrevStmt, logItems.PrevStmt)
}
Expand Down
2 changes: 1 addition & 1 deletion pkg/store/helper/helper.go
Original file line number Diff line number Diff line change
Expand Up @@ -806,7 +806,7 @@ func (h *Helper) GetPDRegionStats(ctx context.Context, tableID int64, noIndexSta
startKey = codec.EncodeBytes([]byte{}, startKey)
endKey = codec.EncodeBytes([]byte{}, endKey)

return pdCli.GetRegionStatusByKeyRange(ctx, pd.NewKeyRange(startKey, endKey))
return pdCli.GetRegionStatusByKeyRange(ctx, pd.NewKeyRange(startKey, endKey), false)
}

// GetTiFlashTableIDFromEndKey computes tableID from pd rule's endKey.
Expand Down
2 changes: 1 addition & 1 deletion pkg/store/mockstore/unistore/pd.go
Original file line number Diff line number Diff line change
Expand Up @@ -165,7 +165,7 @@ func (c *pdClient) SplitAndScatterRegions(ctx context.Context, splitKeys [][]byt
return nil, nil
}

func (c *pdClient) GetRegionFromMember(ctx context.Context, key []byte, memberURLs []string) (*pd.Region, error) {
func (c *pdClient) GetRegionFromMember(ctx context.Context, key []byte, memberURLs []string, opts ...pd.GetRegionOption) (*pd.Region, error) {
return nil, nil
}

Expand Down
2 changes: 1 addition & 1 deletion pkg/store/mockstore/unistore/tikv/mock_region.go
Original file line number Diff line number Diff line change
Expand Up @@ -854,7 +854,7 @@ func (pd *MockPD) GetAllStores(ctx context.Context, opts ...pdclient.GetStoreOpt
// Limit limits the maximum number of regions returned.
// If a region has no leader, corresponding leader will be placed by a peer
// with empty value (PeerID is 0).
func (pd *MockPD) ScanRegions(ctx context.Context, startKey []byte, endKey []byte, limit int) ([]*pdclient.Region, error) {
func (pd *MockPD) ScanRegions(ctx context.Context, startKey []byte, endKey []byte, limit int, opts ...pdclient.GetRegionOption) ([]*pdclient.Region, error) {
regions := pd.rm.ScanRegions(startKey, endKey, limit)
return regions, nil
}
Expand Down