From 3ca872817c594ea2529c59aac98c0f720cad0f36 Mon Sep 17 00:00:00 2001 From: crazycs Date: Tue, 20 Aug 2019 19:00:36 +0800 Subject: [PATCH 1/4] *: record index name in slow log instead of index id --- executor/adapter.go | 12 ++++++------ executor/builder.go | 4 ++-- infoschema/slow_log.go | 4 ++-- sessionctx/stmtctx/stmtctx.go | 4 ++-- sessionctx/variable/session.go | 12 ++++++------ sessionctx/variable/session_test.go | 4 ++-- util/expensivequery/expensivequery.go | 8 ++++---- 7 files changed, 24 insertions(+), 24 deletions(-) diff --git a/executor/adapter.go b/executor/adapter.go index 194338796b80a..016088a4e7b44 100644 --- a/executor/adapter.go +++ b/executor/adapter.go @@ -649,12 +649,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() @@ -662,10 +662,10 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool) { memMax := sessVars.StmtCtx.MemTracker.MaxConsumed() if costTime < threshold { _, digest := sessVars.StmtCtx.SQLDigest() - logutil.SlowQueryLogger.Debug(sessVars.SlowLogFormat(txnTS, costTime, execDetail, indexIDs, digest, statsInfos, copTaskInfo, memMax, succ, sql)) + logutil.SlowQueryLogger.Debug(sessVars.SlowLogFormat(txnTS, costTime, execDetail, indexNames, digest, statsInfos, copTaskInfo, memMax, succ, sql)) } else { _, digest := sessVars.StmtCtx.SQLDigest() - logutil.SlowQueryLogger.Warn(sessVars.SlowLogFormat(txnTS, costTime, execDetail, indexIDs, digest, statsInfos, copTaskInfo, memMax, succ, sql)) + logutil.SlowQueryLogger.Warn(sessVars.SlowLogFormat(txnTS, costTime, execDetail, indexNames, digest, statsInfos, copTaskInfo, memMax, succ, sql)) metrics.TotalQueryProcHistogram.Observe(costTime.Seconds()) metrics.TotalCopProcHistogram.Observe(execDetail.ProcessTime.Seconds()) metrics.TotalCopWaitHistogram.Observe(execDetail.WaitTime.Seconds()) @@ -685,7 +685,7 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool) { User: userString, DB: sessVars.CurrentDB, TableIDs: tableIDs, - IndexIDs: indexIDs, + IndexIDs: indexNames, Internal: sessVars.InRestrictedSQL, }) } diff --git a/executor/builder.go b/executor/builder.go index 489ceeb9670ce..7d20c57eb402b 100644 --- a/executor/builder.go +++ b/executor/builder.go @@ -1889,7 +1889,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.Index.Name.O) return ret } @@ -1968,7 +1968,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.Index.Name.O) sctx.TableIDs = append(sctx.TableIDs, ts.Table.ID) return ret } diff --git a/infoschema/slow_log.go b/infoschema/slow_log.go index 62599420629b6..3096bfb72546d 100644 --- a/infoschema/slow_log.go +++ b/infoschema/slow_log.go @@ -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}, @@ -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" diff --git a/sessionctx/stmtctx/stmtctx.go b/sessionctx/stmtctx/stmtctx.go index 1fd16287633ef..a7ef3c75bd8e3 100644 --- a/sessionctx/stmtctx/stmtctx.go +++ b/sessionctx/stmtctx/stmtctx.go @@ -124,7 +124,7 @@ type StatementContext struct { MemTracker *memory.Tracker RuntimeStatsColl *execdetails.RuntimeStatsColl TableIDs []int64 - IndexIDs []int64 + IndexNames []string nowTs time.Time // use this variable for now/current_timestamp calculation/cache for one stmt stmtTimeCached bool StmtType string @@ -412,7 +412,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] } // MergeExecDetails merges a single region execution details into self, used to print diff --git a/sessionctx/variable/session.go b/sessionctx/variable/session.go index dede1b68640fe..1726ae3151777 100644 --- a/sessionctx/variable/session.go +++ b/sessionctx/variable/session.go @@ -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. @@ -1042,7 +1042,7 @@ const ( // # 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: [idx1,idx2] // # Is_internal: false // # Digest: 42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772 // # Stats: t1:1,t2:2 @@ -1052,7 +1052,7 @@ const ( // # Memory_max: 4096 // # Succ: true // select * from t_slim; -func (s *SessionVars) SlowLogFormat(txnTS uint64, costTime time.Duration, execDetail execdetails.ExecDetails, indexIDs string, digest string, +func (s *SessionVars) SlowLogFormat(txnTS uint64, costTime time.Duration, execDetail execdetails.ExecDetails, indexNames string, digest string, statsInfos map[string]uint64, copTasks *stmtctx.CopTasksDetails, memMax int64, succ bool, sql string) string { var buf bytes.Buffer execDetailStr := execDetail.String() @@ -1070,8 +1070,8 @@ func (s *SessionVars) SlowLogFormat(txnTS uint64, costTime time.Duration, execDe if len(s.CurrentDB) > 0 { buf.WriteString(SlowLogRowPrefixStr + SlowLogDBStr + SlowLogSpaceMarkStr + s.CurrentDB + "\n") } - if len(indexIDs) > 0 { - buf.WriteString(SlowLogRowPrefixStr + SlowLogIndexIDsStr + SlowLogSpaceMarkStr + indexIDs + "\n") + if len(indexNames) > 0 { + buf.WriteString(SlowLogRowPrefixStr + SlowLogIndexNamesStr + SlowLogSpaceMarkStr + indexNames + "\n") } buf.WriteString(SlowLogRowPrefixStr + SlowLogIsInternalStr + SlowLogSpaceMarkStr + strconv.FormatBool(s.InRestrictedSQL) + "\n") if len(digest) > 0 { diff --git a/sessionctx/variable/session_test.go b/sessionctx/variable/session_test.go index 179579ce8b5e9..8eb876043147e 100644 --- a/sessionctx/variable/session_test.go +++ b/sessionctx/variable/session_test.go @@ -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: [a,b] # Is_internal: true # Digest: 42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772 # Stats: t1:pseudo @@ -170,6 +170,6 @@ func (*testSessionSuite) TestSlowLogFormat(c *C) { select * from t;` sql := "select * from t" digest := parser.DigestHash(sql) - logString := seVar.SlowLogFormat(txnTS, costTime, execDetail, "[1,2]", digest, statsInfos, copTasks, memMax, true, sql) + logString := seVar.SlowLogFormat(txnTS, costTime, execDetail, "[a,b]", digest, statsInfos, copTasks, memMax, true, sql) c.Assert(logString, Equals, resultString) } diff --git a/util/expensivequery/expensivequery.go b/util/expensivequery/expensivequery.go index c407a27c8ba57..996a53dcdf7be 100644 --- a/util/expensivequery/expensivequery.go +++ b/util/expensivequery/expensivequery.go @@ -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 { From 39b0038e51eb7b8afaa59819a08c664d0322307e Mon Sep 17 00:00:00 2001 From: crazycs Date: Tue, 20 Aug 2019 23:56:30 +0800 Subject: [PATCH 2/4] fmt code --- executor/adapter.go | 4 ++-- sessionctx/variable/session.go | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/executor/adapter.go b/executor/adapter.go index d6664886726ad..4015a22219000 100644 --- a/executor/adapter.go +++ b/executor/adapter.go @@ -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, - IndexNames: indexNames, + IndexNames: indexNames, StatsInfos: statsInfos, CopTasks: copTaskInfo, ExecDetail: execDetail, @@ -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, - IndexNames: indexNames, + IndexNames: indexNames, StatsInfos: statsInfos, CopTasks: copTaskInfo, ExecDetail: execDetail, diff --git a/sessionctx/variable/session.go b/sessionctx/variable/session.go index db1f7f4d7db86..fe937271dfd0b 100644 --- a/sessionctx/variable/session.go +++ b/sessionctx/variable/session.go @@ -1042,7 +1042,7 @@ type SlowQueryLogItems struct { TimeTotal time.Duration TimeParse time.Duration TimeCompile time.Duration - IndexNames string + IndexNames string StatsInfos map[string]uint64 CopTasks *stmtctx.CopTasksDetails ExecDetail execdetails.ExecDetails From a4d5909ec8e20477f040034bfdce1ed68ddb5ebe Mon Sep 17 00:00:00 2001 From: crazycs Date: Wed, 21 Aug 2019 09:51:08 +0800 Subject: [PATCH 3/4] address comment --- executor/builder.go | 4 ++-- sessionctx/variable/session.go | 2 +- sessionctx/variable/session_test.go | 4 ++-- 3 files changed, 5 insertions(+), 5 deletions(-) diff --git a/executor/builder.go b/executor/builder.go index 6a5a611f35655..8dcfa9ace2534 100644 --- a/executor/builder.go +++ b/executor/builder.go @@ -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.IndexNames = append(sctx.IndexNames, is.Index.Name.O) + sctx.IndexNames = append(sctx.IndexNames, is.Table.Name.O+":"+is.Index.Name.O) return ret } @@ -2008,7 +2008,7 @@ func (b *executorBuilder) buildIndexLookUpReader(v *plannercore.PhysicalIndexLoo ret.ranges = is.Ranges executorCounterIndexLookUpExecutor.Inc() sctx := b.ctx.GetSessionVars().StmtCtx - sctx.IndexNames = append(sctx.IndexNames, is.Index.Name.O) + sctx.IndexNames = append(sctx.IndexNames, is.Table.Name.O+":"+is.Index.Name.O) sctx.TableIDs = append(sctx.TableIDs, ts.Table.ID) return ret } diff --git a/sessionctx/variable/session.go b/sessionctx/variable/session.go index fe937271dfd0b..3e75472ff5f6e 100644 --- a/sessionctx/variable/session.go +++ b/sessionctx/variable/session.go @@ -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_names: [idx1,idx2] +// # Index_names: [t1.idx1,t2.idx2] // # Is_internal: false // # Digest: 42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772 // # Stats: t1:1,t2:2 diff --git a/sessionctx/variable/session_test.go b/sessionctx/variable/session_test.go index a4397ef81e786..7e1a5716a20c1 100644 --- a/sessionctx/variable/session_test.go +++ b/sessionctx/variable/session_test.go @@ -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_names: [a,b] +# Index_names: [t1:a,t2:b] # Is_internal: true # Digest: 42a1c8aae6f133e934d4bf0147491709a8812ea05ff8819ec522780fe657b772 # Stats: t1:pseudo @@ -177,7 +177,7 @@ select * from t;` TimeTotal: costTime, TimeParse: time.Duration(10), TimeCompile: time.Duration(10), - IndexNames: "[a,b]", + IndexNames: "[t1:a,t2:b]", StatsInfos: statsInfos, CopTasks: copTasks, ExecDetail: execDetail, From f035eb4fe7cac4ad64caa7faa287fd2c54744738 Mon Sep 17 00:00:00 2001 From: crazycs Date: Thu, 22 Aug 2019 11:02:31 +0800 Subject: [PATCH 4/4] address comment --- domain/topn_slow_query.go | 26 +++++++++++++------------- executor/adapter.go | 26 +++++++++++++------------- executor/executor.go | 2 +- 3 files changed, 27 insertions(+), 27 deletions(-) diff --git a/domain/topn_slow_query.go b/domain/topn_slow_query.go index f280a6c43ab9a..ee014387c3a8b 100644 --- a/domain/topn_slow_query.go +++ b/domain/topn_slow_query.go @@ -213,17 +213,17 @@ func (q *topNSlowQueries) Close() { // SlowQueryInfo is a struct to record slow query info. type SlowQueryInfo struct { - SQL string - Start time.Time - Duration time.Duration - Detail execdetails.ExecDetails - ConnID uint64 - TxnTS uint64 - User string - DB string - TableIDs string - IndexIDs string - Digest string - Internal bool - Succ bool + SQL string + Start time.Time + Duration time.Duration + Detail execdetails.ExecDetails + ConnID uint64 + TxnTS uint64 + User string + DB string + TableIDs string + IndexNames string + Digest string + Internal bool + Succ bool } diff --git a/executor/adapter.go b/executor/adapter.go index 4015a22219000..2f489b9b4b2fb 100644 --- a/executor/adapter.go +++ b/executor/adapter.go @@ -704,19 +704,19 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool) { userString = sessVars.User.String() } domain.GetDomain(a.Ctx).LogSlowQuery(&domain.SlowQueryInfo{ - SQL: sql, - Digest: digest, - Start: a.Ctx.GetSessionVars().StmtCtx.StartTime, - Duration: costTime, - Detail: sessVars.StmtCtx.GetExecDetails(), - Succ: succ, - ConnID: sessVars.ConnectionID, - TxnTS: txnTS, - User: userString, - DB: sessVars.CurrentDB, - TableIDs: tableIDs, - IndexIDs: indexNames, - Internal: sessVars.InRestrictedSQL, + SQL: sql, + Digest: digest, + Start: a.Ctx.GetSessionVars().StmtCtx.StartTime, + Duration: costTime, + Detail: sessVars.StmtCtx.GetExecDetails(), + Succ: succ, + ConnID: sessVars.ConnectionID, + TxnTS: txnTS, + User: userString, + DB: sessVars.CurrentDB, + TableIDs: tableIDs, + IndexNames: indexNames, + Internal: sessVars.InRestrictedSQL, }) } } diff --git a/executor/executor.go b/executor/executor.go index 0663770c30914..88f109fdc322f 100644 --- a/executor/executor.go +++ b/executor/executor.go @@ -728,7 +728,7 @@ func (e *ShowSlowExec) Next(ctx context.Context, req *chunk.Chunk) error { req.AppendString(7, slow.User) req.AppendString(8, slow.DB) req.AppendString(9, slow.TableIDs) - req.AppendString(10, slow.IndexIDs) + req.AppendString(10, slow.IndexNames) if slow.Internal { req.AppendInt64(11, 1) } else {