introduce tracing framework

Signed-off-by: zhongzc <zhongzc_arch@outlook.com>

integration

Signed-off-by: zhongzc <zhongzc_arch@outlook.com>

support local storage

Signed-off-by: Zhenchi <zhongzc_arch@outlook.com>

.gitignore

@@ -18,3 +18,4 @@ vendor
 /_tools/
 .DS_Store
 .vscode
+tmp

config/config.go

@@ -186,6 +186,8 @@ type Config struct {
 	// EnableTCP4Only enables net.Listen("tcp4",...)
 	// Note that: it can make lvs with toa work and thus tidb can get real client ip.
 	EnableTCP4Only bool `toml:"enable-tcp4-only" json:"enable-tcp4-only"`
+	// Trace enables timeline tracing.
+	Trace Trace `toml:"trace" json:"trace"`
 }
 
 // UpdateTempStoragePath is to update the `TempStoragePath` if port/statusPort was changed
@@ -632,6 +634,20 @@ type IsolationRead struct {
 	Engines []string `toml:"engines" json:"engines"`
 }
 
+// Trace is the config for timeline tracing.
+type Trace struct {
+	// Enable timeline tracing or not.
+	Enable bool `toml:"enable" json:"enable"`
+	// Directory to store tracing results.
+	StorageDir string `toml:"storage-dir" json:"storage-dir"`
+	// Jaeger agent to report tracing results.
+	JaegerThriftCompactAgent string `toml:"jaeger-thrift-compact-agent" json:"jaeger-thrift-compact-agent"`
+	// Datadog agent to report tracing results.
+	DatadogAgent string `toml:"datadog-agent" json:"datadog-agent"`
+	// The maximum length of spans produced by TiDB to report per SQL.
+	MaxSpansLength int64 `toml:"max-spans-length" json:"max-spans-length"`
+}
+
 // Experimental controls the features that are still experimental: their semantics, interfaces are subject to change.
 // Using these features in the production environment is not recommended.
 type Experimental struct {
@@ -812,6 +828,13 @@ var defaultConf = Config{
 	TxnScope:                     DefTxnScope,
 	EnableEnumLengthLimit:        true,
 	StoresRefreshInterval:        DefStoresRefreshInterval,
+	Trace: Trace{
+		Enable:                   false,
+		StorageDir:               "tidb.trace",
+		JaegerThriftCompactAgent: "",
+		DatadogAgent:             "",
+		MaxSpansLength:           2000,
+	},
 }
 
 var (

config/config.toml.example

@@ -497,3 +497,19 @@ enable-global-kill = false
 [isolation-read]
 # engines means allow the tidb server read data from which types of engines. options: "tikv", "tiflash", "tidb".
 engines = ["tikv", "tiflash", "tidb"]
+
+[trace]
+# Enable timeline tracing
+enable = false
+
+# Directory to store tracing results
+storage-dir = "tidb.trace"
+
+# Jaeger agent to report trace results. Commonly, it's set to "127.0.0.1:6831".
+jaeger-thrift-compact-agent = ""
+
+# Datadog agent to report trace results. Commonly, it's set to "127.0.0.1:8126".
+datadog-agent = ""
+
+# The maximum length of spans to report for each SQL.
+max-spans-length = 2000

distsql/distsql.go

@@ -26,6 +26,7 @@ import (
 	"github.com/pingcap/tidb/types"
 	"github.com/pingcap/tidb/util/memory"
 	"github.com/pingcap/tipb/go-tipb"
+	"github.com/tikv/minitrace-go"
 )
 
 // DispatchMPPTasks dispathes all tasks and returns an iterator.
@@ -65,6 +66,9 @@ func Select(ctx context.Context, sctx sessionctx.Context, kvReq *kv.Request, fie
 		ctx = opentracing.ContextWithSpan(ctx, span1)
 	}
 
+	ctx, span := minitrace.StartSpanWithContext(ctx, "distsql.Select")
+	defer span.Finish()
+
 	// For testing purpose.
 	if hook := ctx.Value("CheckSelectRequestHook"); hook != nil {
 		hook.(func(*kv.Request))(kvReq)

executor/adapter.go

@@ -44,6 +44,7 @@ import (
 	"github.com/pingcap/tidb/sessionctx"
 	"github.com/pingcap/tidb/sessionctx/variable"
 	"github.com/pingcap/tidb/store/tikv"
+	tidbtrace "github.com/pingcap/tidb/trace"
 	"github.com/pingcap/tidb/types"
 	"github.com/pingcap/tidb/util/chunk"
 	"github.com/pingcap/tidb/util/execdetails"
@@ -54,6 +55,7 @@ import (
 	"github.com/pingcap/tidb/util/sqlexec"
 	"github.com/pingcap/tidb/util/stmtsummary"
 	"github.com/pingcap/tidb/util/stringutil"
+	"github.com/tikv/minitrace-go"
 	"go.uber.org/zap"
 	"go.uber.org/zap/zapcore"
 )
@@ -207,6 +209,9 @@ func (a *ExecStmt) PointGet(ctx context.Context, is infoschema.InfoSchema) (*rec
 		defer span1.Finish()
 		ctx = opentracing.ContextWithSpan(ctx, span1)
 	}
+	ctx, span := minitrace.StartSpanWithContext(ctx, "ExecStmt.PointGet")
+	defer span.Finish()
+
 	startTs := uint64(math.MaxUint64)
 	err := a.Ctx.InitTxnWithStartTS(startTs)
 	if err != nil {
@@ -512,6 +517,8 @@ func (a *ExecStmt) handleNoDelayExecutor(ctx context.Context, e Executor) (sqlex
 		defer span1.Finish()
 		ctx = opentracing.ContextWithSpan(ctx, span1)
 	}
+	ctx, span := minitrace.StartSpanWithContext(ctx, "executor.handleNoDelayExecutor")
+	defer span.Finish()
 
 	// Check if "tidb_snapshot" is set for the write executors.
 	// In history read mode, we can not do write operations.
@@ -926,6 +933,13 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool, hasMoreResults bool) {
 	memMax := sessVars.StmtCtx.MemTracker.MaxConsumed()
 	diskMax := sessVars.StmtCtx.DiskTracker.MaxConsumed()
 	_, planDigest := getPlanDigest(a.Ctx, a.Plan)
+	_, traceID, isEnable := minitrace.CurrentID(a.GoCtx)
+	if isEnable {
+		minitrace.AccessAttachment(a.GoCtx, func(attachment interface{}) {
+			c := attachment.(*tidbtrace.Context)
+			c.ShouldReport = true
+		})
+	}
 	slowItems := &variable.SlowQueryLogItems{
 		TxnTS:             txnTS,
 		SQL:               sql.String(),
@@ -954,6 +968,7 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool, hasMoreResults bool) {
 		BackoffTotal:      time.Duration(atomic.LoadInt64(&stmtDetail.BackoffDuration)),
 		WriteSQLRespTotal: stmtDetail.WriteSQLRespDuration,
 		ExecRetryCount:    a.retryCount,
+		TraceID:           traceID,
 	}
 	if a.retryCount > 0 {
 		slowItems.ExecRetryTime = costTime - sessVars.DurationParse - sessVars.DurationCompile - time.Since(a.retryStartTime)

executor/compiler.go

@@ -25,6 +25,7 @@ import (
 	"github.com/pingcap/tidb/planner"
 	plannercore "github.com/pingcap/tidb/planner/core"
 	"github.com/pingcap/tidb/sessionctx"
+	"github.com/tikv/minitrace-go"
 )
 
 var (
@@ -52,6 +53,8 @@ func (c *Compiler) Compile(ctx context.Context, stmtNode ast.StmtNode) (*ExecStm
 		defer span1.Finish()
 		ctx = opentracing.ContextWithSpan(ctx, span1)
 	}
+	ctx, span := minitrace.StartSpanWithContext(ctx, "executor.Compile")
+	defer span.Finish()
 
 	infoSchema := infoschema.GetInfoSchema(c.Ctx)
 	if err := plannercore.Preprocess(c.Ctx, stmtNode, infoSchema); err != nil {

executor/executor.go

@@ -59,6 +59,7 @@ import (
 	"github.com/pingcap/tidb/util/execdetails"
 	"github.com/pingcap/tidb/util/logutil"
 	"github.com/pingcap/tidb/util/memory"
+	"github.com/tikv/minitrace-go"
 	"go.uber.org/zap"
 )
 
@@ -272,6 +273,8 @@ func Next(ctx context.Context, e Executor, req *chunk.Chunk) error {
 		defer span1.Finish()
 		ctx = opentracing.ContextWithSpan(ctx, span1)
 	}
+	ctx, span := minitrace.StartSpanWithContext(ctx, fmt.Sprintf("%T.Next", e))
+	defer span.Finish()
 	if trace.IsEnabled() {
 		defer trace.StartRegion(ctx, fmt.Sprintf("%T.Next", e)).End()
 	}
@@ -1141,6 +1144,9 @@ func init() {
 			ctx = opentracing.ContextWithSpan(ctx, span1)
 		}
 
+		ctx, span := minitrace.StartSpanWithContext(ctx, "executor.EvalSubQuery")
+		defer span.Finish()
+
 		e := &executorBuilder{is: is, ctx: sctx}
 		exec := e.build(p)
 		if e.err != nil {

executor/insert.go

@@ -31,6 +31,7 @@ import (
 	"github.com/pingcap/tidb/util/logutil"
 	"github.com/pingcap/tidb/util/memory"
 	"github.com/pingcap/tidb/util/stringutil"
+	"github.com/tikv/minitrace-go"
 	"go.uber.org/zap"
 )
 
@@ -116,7 +117,8 @@ func prefetchUniqueIndices(ctx context.Context, txn kv.Transaction, rows []toBeC
 		defer span1.Finish()
 		ctx = opentracing.ContextWithSpan(ctx, span1)
 	}
-
+	ctx, span := minitrace.StartSpanWithContext(ctx, "prefetchUniqueIndices")
+	defer span.Finish()
 	nKeys := 0
 	for _, r := range rows {
 		if r.ignored {
@@ -148,7 +150,8 @@ func prefetchConflictedOldRows(ctx context.Context, txn kv.Transaction, rows []t
 		defer span1.Finish()
 		ctx = opentracing.ContextWithSpan(ctx, span1)
 	}
-
+	ctx, span := minitrace.StartSpanWithContext(ctx, "prefetchConflictedOldRows")
+	defer span.Finish()
 	batchKeys := make([]kv.Key, 0, len(rows))
 	for _, r := range rows {
 		for _, uk := range r.uniqueKeys {
@@ -171,6 +174,8 @@ func prefetchDataCache(ctx context.Context, txn kv.Transaction, rows []toBeCheck
 		defer span1.Finish()
 		ctx = opentracing.ContextWithSpan(ctx, span1)
 	}
+	ctx, span := minitrace.StartSpanWithContext(ctx, "prefetchDataCache")
+	defer span.Finish()
 	values, err := prefetchUniqueIndices(ctx, txn, rows)
 	if err != nil {
 		return err

executor/insert_common.go

@@ -40,6 +40,7 @@ import (
 	"github.com/pingcap/tidb/util/dbterror"
 	"github.com/pingcap/tidb/util/execdetails"
 	"github.com/pingcap/tidb/util/memory"
+	"github.com/tikv/minitrace-go"
 )
 
 // InsertValues is the data to insert.
@@ -1018,6 +1019,8 @@ func (e *InsertValues) batchCheckAndInsert(ctx context.Context, rows [][]types.D
 		defer span1.Finish()
 		opentracing.ContextWithSpan(ctx, span1)
 	}
+	ctx, span := minitrace.StartSpanWithContext(ctx, "InsertValues.batchCheckAndInsert")
+	defer span.Finish()
 	start := time.Now()
 	// Get keys need to be checked.
 	toBeCheckedRows, err := getKeysNeedCheck(ctx, e.ctx, e.Table, rows)

executor/partition_table.go

@@ -24,6 +24,7 @@ import (
 	"github.com/pingcap/tidb/util/chunk"
 	"github.com/pingcap/tidb/util/ranger"
 	"github.com/pingcap/tipb/go-tipb"
+	"github.com/tikv/minitrace-go"
 )
 
 // PartitionTableExecutor is a Executor for partitioned table.
@@ -145,6 +146,8 @@ func nextPartitionWithTrace(ctx context.Context, n nextPartition, tbl table.Phys
 		defer span1.Finish()
 		ctx = opentracing.ContextWithSpan(ctx, span1)
 	}
+	ctx, span := minitrace.StartSpanWithContext(ctx, fmt.Sprintf("nextPartition %d", tbl.GetPhysicalID()))
+	defer span.Finish()
 	return n.nextPartition(ctx, tbl)
 }
 

executor/slow_query.go

@@ -661,6 +661,7 @@ type slowQueryTuple struct {
 	rocksdbBlockCacheCount    uint64
 	rocksdbBlockReadCount     uint64
 	rocksdbBlockReadByte      uint64
+	traceID                   uint64
 }
 
 func (st *slowQueryTuple) setFieldValue(tz *time.Location, field, value string, lineNum int, checker *slowLogChecker) (valid bool, err error) {
@@ -837,6 +838,8 @@ func (st *slowQueryTuple) setFieldValue(tz *time.Location, field, value string,
 			st.backoffDetail += " "
 		}
 		st.backoffDetail += value
+	case variable.SlowLogTraceID:
+		st.traceID, err = strconv.ParseUint(value, 10, 64)
 	}
 	if err != nil {
 		return valid, fmt.Errorf("Parse slow log at line " + strconv.FormatInt(int64(lineNum), 10) + " failed. Field: `" + field + "`, error: " + err.Error())
@@ -929,6 +932,7 @@ func (st *slowQueryTuple) convertToDatumRow() []types.Datum {
 	}
 	record = append(record, types.NewStringDatum(parsePlan(st.plan)))
 	record = append(record, types.NewStringDatum(st.planDigest))
+	record = append(record, types.NewUintDatum(st.traceID))
 	record = append(record, types.NewStringDatum(st.prevStmt))
 	record = append(record, types.NewStringDatum(st.sql))
 	return record

executor/slow_query_test.go

@@ -73,6 +73,7 @@ func (s *testExecSerialSuite) TestParseSlowLogPanic(c *C) {
 # Plan_from_binding: true
 # Succ: false
 # Plan_digest: 60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4
+# Trace_ID: 3158789592171458600
 # Prev_stmt: update t set i = 1;
 use test;
 select * from t;`
@@ -113,6 +114,7 @@ func (s *testExecSuite) TestParseSlowLogFile(c *C) {
 # Plan_from_binding: true
 # Succ: false
 # Plan_digest: 60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4
+# Trace_ID: 3158789592171458600
 # Prev_stmt: update t set i = 1;
 use test;
 select * from t;`
@@ -138,7 +140,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,` +
 		`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,1,,60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4,` +
+		`0,0,1,1,,60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4,3158789592171458600,` +
 		`update t set i = 1;,select * from t;`
 	c.Assert(expectRecordString, Equals, recordString)
 
@@ -161,7 +163,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,` +
 		`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,1,,60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4,` +
+		`0,0,1,1,,60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4,3158789592171458600,` +
 		`update t set i = 1;,select * from t;`
 	c.Assert(expectRecordString, Equals, recordString)
 
@@ -283,6 +285,7 @@ select * from t
 # Cop_wait_avg: 0.05 Cop_wait_p90: 0.6 Cop_wait_max: 0.8
 # Mem_max: 70724
 # Plan_digest: 60e9378c746d9a2be1c791047e008967cf252eb6de9167ad3aa6098fa2d523f4
+# Trace_ID: 3158789592171458600
 select * from t;`)
 	scanner := bufio.NewReader(slowLog)
 	loc, err := time.LoadLocation("Asia/Shanghai")

executor/table_reader.go

@@ -34,6 +34,7 @@ import (
 	"github.com/pingcap/tidb/util/ranger"
 	"github.com/pingcap/tidb/util/stringutil"
 	"github.com/pingcap/tipb/go-tipb"
+	"github.com/tikv/minitrace-go"
 )
 
 // make sure `TableReaderExecutor` implements `Executor`.
@@ -114,6 +115,9 @@ func (e *TableReaderExecutor) Open(ctx context.Context) error {
 		ctx = opentracing.ContextWithSpan(ctx, span1)
 	}
 
+	ctx, span := minitrace.StartSpanWithContext(ctx, "TableReaderExecutor.Open")
+	defer span.Finish()
+
 	e.memTracker = memory.NewTracker(e.id, -1)
 	e.memTracker.AttachTo(e.ctx.GetSessionVars().StmtCtx.MemTracker)
 

executor/write.go

@@ -34,6 +34,7 @@ import (
 	"github.com/pingcap/tidb/types"
 	"github.com/pingcap/tidb/util/codec"
 	"github.com/pingcap/tidb/util/memory"
+	"github.com/tikv/minitrace-go"
 )
 
 var (
@@ -57,6 +58,8 @@ func updateRecord(ctx context.Context, sctx sessionctx.Context, h kv.Handle, old
 		defer span1.Finish()
 		ctx = opentracing.ContextWithSpan(ctx, span1)
 	}
+	ctx, span := minitrace.StartSpanWithContext(ctx, "executor.updateRecord")
+	defer span.Finish()
 	txn, err := sctx.Txn(false)
 	if err != nil {
 		return false, err