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.

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

Jump to bottom

*: record index name in the slow log instead of index id #11795

Merged
merged 10 commits into from
Aug 22, 2019
Merged

*: record index name in the slow log instead of index id #11795

Show file tree
Hide file tree
Changes from 6 commits
Commits
Show all changes
10 commits
Select commit Hold shift + click to select a range
3ca8728
*: record index name in slow log instead of index id
crazycs520 Aug 20, 2019
3031981
Merge branch 'master' into log-index-name
crazycs520 Aug 20, 2019
9c145f6
Merge branch 'master' of https://github.com/pingcap/tidb into log-ind…
crazycs520 Aug 20, 2019
21cc462
Merge branch 'log-index-name' of https://github.com/crazycs520/tidb i…
crazycs520 Aug 20, 2019
39b0038
fmt code
crazycs520 Aug 20, 2019
a4d5909
address comment
crazycs520 Aug 21, 2019
f035eb4
address comment
crazycs520 Aug 22, 2019
7fd6bb4
Merge branch 'master' into log-index-name
crazycs520 Aug 22, 2019
9ac74a4
Merge branch 'master' into log-index-name
crazycs520 Aug 22, 2019
cd414ad
Merge branch 'master' into log-index-name
ngaut Aug 22, 2019
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
12 changes: 6 additions & 6 deletions executor/adapter.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -653,12 +653,12 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool) {
}
sql = QueryReplacer.Replace(sql) + sessVars.GetExecuteArgumentsInfo()

var tableIDs, indexIDs string
var tableIDs, indexNames string
if len(sessVars.StmtCtx.TableIDs) > 0 {
tableIDs = strings.Replace(fmt.Sprintf("%v", a.Ctx.GetSessionVars().StmtCtx.TableIDs), " ", ",", -1)
}
if len(sessVars.StmtCtx.IndexIDs) > 0 {
indexIDs = strings.Replace(fmt.Sprintf("%v", a.Ctx.GetSessionVars().StmtCtx.IndexIDs), " ", ",", -1)
if len(sessVars.StmtCtx.IndexNames) > 0 {
indexNames = strings.Replace(fmt.Sprintf("%v", a.Ctx.GetSessionVars().StmtCtx.IndexNames), " ", ",", -1)
}
execDetail := sessVars.StmtCtx.GetExecDetails()
copTaskInfo := sessVars.StmtCtx.CopTasksDetails()
Expand All @@ -673,7 +673,7 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool) {
TimeTotal: costTime,
TimeParse: a.Ctx.GetSessionVars().StmtCtx.DurationParse,
TimeCompile: a.Ctx.GetSessionVars().StmtCtx.DurationCompile,
IndexIDs: indexIDs,
IndexNames: indexNames,
StatsInfos: statsInfos,
CopTasks: copTaskInfo,
ExecDetail: execDetail,
Expand All @@ -689,7 +689,7 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool) {
TimeTotal: costTime,
TimeParse: a.Ctx.GetSessionVars().StmtCtx.DurationParse,
TimeCompile: a.Ctx.GetSessionVars().StmtCtx.DurationCompile,
IndexIDs: indexIDs,
IndexNames: indexNames,
StatsInfos: statsInfos,
CopTasks: copTaskInfo,
ExecDetail: execDetail,
Expand All @@ -715,7 +715,7 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool) {
User: userString,
DB: sessVars.CurrentDB,
TableIDs: tableIDs,
IndexIDs: indexIDs,
crazycs520 marked this conversation as resolved.
Show resolved Hide resolved
IndexIDs: indexNames,
Internal: sessVars.InRestrictedSQL,
})
}
Expand Down
4 changes: 2 additions & 2 deletions executor/builder.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1929,7 +1929,7 @@ func (b *executorBuilder) buildIndexReader(v *plannercore.PhysicalIndexReader) *
is := v.IndexPlans[0].(*plannercore.PhysicalIndexScan)
ret.ranges = is.Ranges
sctx := b.ctx.GetSessionVars().StmtCtx
sctx.IndexIDs = append(sctx.IndexIDs, is.Index.ID)
sctx.IndexNames = append(sctx.IndexNames, is.Table.Name.O+":"+is.Index.Name.O)
return ret
}

Expand Down Expand Up @@ -2008,7 +2008,7 @@ func (b *executorBuilder) buildIndexLookUpReader(v *plannercore.PhysicalIndexLoo
ret.ranges = is.Ranges
executorCounterIndexLookUpExecutor.Inc()
sctx := b.ctx.GetSessionVars().StmtCtx
sctx.IndexIDs = append(sctx.IndexIDs, is.Index.ID)
sctx.IndexNames = append(sctx.IndexNames, is.Table.Name.O+":"+is.Index.Name.O)
sctx.TableIDs = append(sctx.TableIDs, ts.Table.ID)
return ret
}
Expand Down
4 changes: 2 additions & 2 deletions infoschema/slow_log.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -46,7 +46,7 @@ var slowQueryCols = []columnInfo{
{execdetails.TotalKeysStr, mysql.TypeLonglong, 20, mysql.UnsignedFlag, nil, nil},
{execdetails.ProcessKeysStr, mysql.TypeLonglong, 20, mysql.UnsignedFlag, nil, nil},
{variable.SlowLogDBStr, mysql.TypeVarchar, 64, 0, nil, nil},
{variable.SlowLogIndexIDsStr, mysql.TypeVarchar, 100, 0, nil, nil},
{variable.SlowLogIndexNamesStr, mysql.TypeVarchar, 100, 0, nil, nil},
{variable.SlowLogIsInternalStr, mysql.TypeTiny, 1, 0, nil, nil},
{variable.SlowLogDigestStr, mysql.TypeVarchar, 64, 0, nil, nil},
{variable.SlowLogStatsInfoStr, mysql.TypeVarchar, 512, 0, nil, nil},
Expand Down Expand Up @@ -239,7 +239,7 @@ func (st *slowQueryTuple) setFieldValue(tz *time.Location, field, value string)
st.processKeys, err = strconv.ParseUint(value, 10, 64)
case variable.SlowLogDBStr:
st.db = value
case variable.SlowLogIndexIDsStr:
case variable.SlowLogIndexNamesStr:
st.indexIDs = value
case variable.SlowLogIsInternalStr:
st.isInternal = value == "true"
Expand Down
4 changes: 2 additions & 2 deletions sessionctx/stmtctx/stmtctx.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -131,7 +131,7 @@ type StatementContext struct {
MemTracker *memory.Tracker
RuntimeStatsColl *execdetails.RuntimeStatsColl
TableIDs []int64
Copy link
Member

Choose a reason for hiding this comment

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

  1. How about using table names as well?
  2. How about using the table_name:index_name format to display table and index names?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

tableIDs is not be printed in the slow log.

Copy link
Member

Choose a reason for hiding this comment

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

If we do not print the table id, how do we know which table is accessed with an index if there are multiple tables doing the join operation?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

How about store table_name:index_name in indexNames?

Copy link
Member

Choose a reason for hiding this comment

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

Sounds reasonable.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

done.

IndexIDs []int64
IndexNames []string
nowTs time.Time // use this variable for now/current_timestamp calculation/cache for one stmt
stmtTimeCached bool
StmtType string
Expand Down Expand Up @@ -419,7 +419,7 @@ func (sc *StatementContext) ResetForRetry() {
sc.mu.allExecDetails = make([]*execdetails.ExecDetails, 0, 4)
sc.mu.Unlock()
sc.TableIDs = sc.TableIDs[:0]
sc.IndexIDs = sc.IndexIDs[:0]
sc.IndexNames = sc.IndexNames[:0]
sc.StartTime = time.Now()
sc.DurationCompile = time.Duration(0)
sc.DurationParse = time.Duration(0)
Expand Down
12 changes: 6 additions & 6 deletions sessionctx/variable/session.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1001,8 +1001,8 @@ const (
SlowLogDBStr = "DB"
// SlowLogIsInternalStr is slow log field name.
SlowLogIsInternalStr = "Is_internal"
// SlowLogIndexIDsStr is slow log field name.
SlowLogIndexIDsStr = "Index_ids"
// SlowLogIndexNamesStr is slow log field name.
SlowLogIndexNamesStr = "Index_names"
// SlowLogDigestStr is slow log field name.
SlowLogDigestStr = "Digest"
// SlowLogQuerySQLStr is slow log field name.
Expand Down Expand Up @@ -1042,7 +1042,7 @@ type SlowQueryLogItems struct {
TimeTotal time.Duration
TimeParse time.Duration
TimeCompile time.Duration
IndexIDs string
IndexNames string
StatsInfos map[string]uint64
CopTasks *stmtctx.CopTasksDetails
ExecDetail execdetails.ExecDetails
Expand All @@ -1059,7 +1059,7 @@ type SlowQueryLogItems struct {
// # Query_time: 4.895492
// # Process_time: 0.161 Request_count: 1 Total_keys: 100001 Processed_keys: 100000
// # DB: test
// # Index_ids: [1,2]
// # Index_names: [t1.idx1,t2.idx2]
// # Is_internal: false
// # Digest: 42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772
// # Stats: t1:1,t2:2
Expand Down Expand Up @@ -1088,8 +1088,8 @@ func (s *SessionVars) SlowLogFormat(logItems *SlowQueryLogItems) string {
if len(s.CurrentDB) > 0 {
writeSlowLogItem(&buf, SlowLogDBStr, s.CurrentDB)
}
if len(logItems.IndexIDs) > 0 {
writeSlowLogItem(&buf, SlowLogIndexIDsStr, logItems.IndexIDs)
if len(logItems.IndexNames) > 0 {
writeSlowLogItem(&buf, SlowLogIndexNamesStr, logItems.IndexNames)
}

writeSlowLogItem(&buf, SlowLogIsInternalStr, strconv.FormatBool(s.InRestrictedSQL))
Expand Down
4 changes: 2 additions & 2 deletions sessionctx/variable/session_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -158,7 +158,7 @@ func (*testSessionSuite) TestSlowLogFormat(c *C) {
# Query_time: 1
# Process_time: 2 Wait_time: 60 Backoff_time: 0.001 Request_count: 2 Total_keys: 10000 Process_keys: 20001
# DB: test
# Index_ids: [1,2]
# Index_names: [t1:a,t2:b]
# Is_internal: true
# Digest: 42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772
# Stats: t1:pseudo
Expand All @@ -177,7 +177,7 @@ select * from t;`
TimeTotal: costTime,
TimeParse: time.Duration(10),
TimeCompile: time.Duration(10),
IndexIDs: "[1,2]",
IndexNames: "[t1:a,t2:b]",
StatsInfos: statsInfos,
CopTasks: copTasks,
ExecDetail: execDetail,
Expand Down
8 changes: 4 additions & 4 deletions util/expensivequery/expensivequery.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -127,14 +127,14 @@ func logExpensiveQuery(costTime time.Duration, info *util.ProcessInfo) {
if len(info.DB) > 0 {
logFields = append(logFields, zap.String("database", info.DB))
}
var tableIDs, indexIDs string
var tableIDs, indexNames string
if len(info.StmtCtx.TableIDs) > 0 {
tableIDs = strings.Replace(fmt.Sprintf("%v", info.StmtCtx.TableIDs), " ", ",", -1)
logFields = append(logFields, zap.String("table_ids", tableIDs))
}
if len(info.StmtCtx.IndexIDs) > 0 {
indexIDs = strings.Replace(fmt.Sprintf("%v", info.StmtCtx.IndexIDs), " ", ",", -1)
logFields = append(logFields, zap.String("index_ids", indexIDs))
if len(info.StmtCtx.IndexNames) > 0 {
indexNames = strings.Replace(fmt.Sprintf("%v", info.StmtCtx.IndexNames), " ", ",", -1)
logFields = append(logFields, zap.String("index_names", indexNames))
}
logFields = append(logFields, zap.Uint64("txn_start_ts", info.CurTxnStartTS))
if memTracker := info.StmtCtx.MemTracker; memTracker != nil {
Expand Down