diff --git a/executor/builder.go b/executor/builder.go index 1992791ba99c8..aed3694fdde3a 100644 --- a/executor/builder.go +++ b/executor/builder.go @@ -89,6 +89,8 @@ func (b *executorBuilder) build(p plan.Plan) Executor { return b.buildDelete(v) case *plan.Execute: return b.buildExecute(v) + case *plan.Trace: + return b.buildTrace(v) case *plan.Explain: return b.buildExplain(v) case *plan.PointGetPlan: @@ -619,6 +621,16 @@ func (b *executorBuilder) buildDDL(v *plan.DDL) Executor { return e } +// buildTrace builds a TraceExec for future executing. This method will be called +// at build(). +func (b *executorBuilder) buildTrace(v *plan.Trace) Executor { + return &TraceExec{ + baseExecutor: newBaseExecutor(b.ctx, v.Schema(), v.ExplainID()), + stmtNode: v.StmtNode, + builder: b, + } +} + // buildExplain builds a explain executor. `e.rows` collects final result to `ExplainExec`. func (b *executorBuilder) buildExplain(v *plan.Explain) Executor { e := &ExplainExec{ diff --git a/executor/distsql.go b/executor/distsql.go index 2cb5ca8e4b5da..b16c04aad1901 100644 --- a/executor/distsql.go +++ b/executor/distsql.go @@ -23,7 +23,6 @@ import ( "unsafe" "github.com/juju/errors" - "github.com/opentracing/opentracing-go" "github.com/pingcap/tidb/distsql" "github.com/pingcap/tidb/expression" "github.com/pingcap/tidb/kv" @@ -210,18 +209,6 @@ func splitRanges(ranges []*ranger.Range, keepOrder bool) ([]*ranger.Range, []*ra return signedRanges, unsignedRanges } -// startSpanFollowContext is similar to opentracing.StartSpanFromContext, but the span reference use FollowsFrom option. -func startSpanFollowsContext(ctx context.Context, operationName string) (opentracing.Span, context.Context) { - span := opentracing.SpanFromContext(ctx) - if span != nil { - span = opentracing.StartSpan(operationName, opentracing.FollowsFrom(span.Context())) - } else { - span = opentracing.StartSpan(operationName) - } - - return span, opentracing.ContextWithSpan(ctx, span) -} - // rebuildIndexRanges will be called if there's correlated column in access conditions. We will rebuild the range // by substitute correlated column with the constant. func rebuildIndexRanges(ctx sessionctx.Context, is *plan.PhysicalIndexScan, idxCols []*expression.Column, colLens []int) (ranges []*ranger.Range, err error) { @@ -298,9 +285,6 @@ func (e *IndexReaderExecutor) Open(ctx context.Context) error { } func (e *IndexReaderExecutor) open(ctx context.Context, kvRanges []kv.KeyRange) error { - span, ctx := startSpanFollowsContext(ctx, "executor.IndexReader.Open") - defer span.Finish() - var err error if e.corColInFilter { e.dagPB.Executors, _, err = constructDistExec(e.ctx, e.plans) @@ -403,9 +387,6 @@ func (e *IndexLookUpExecutor) open(ctx context.Context, kvRanges []kv.KeyRange) e.memTracker = memory.NewTracker(e.id, e.ctx.GetSessionVars().MemQuotaIndexLookupReader) e.memTracker.AttachTo(e.ctx.GetSessionVars().StmtCtx.MemTracker) - span, ctx := startSpanFollowsContext(ctx, "executor.IndexLookUp.Open") - defer span.Finish() - e.finished = make(chan struct{}) e.resultCh = make(chan *lookupTableTask, atomic.LoadInt32(&LookupTableTaskChannelSize)) diff --git a/executor/table_reader.go b/executor/table_reader.go index a2e7abe88b446..b3aa6a1c3f0cf 100644 --- a/executor/table_reader.go +++ b/executor/table_reader.go @@ -57,9 +57,6 @@ type TableReaderExecutor struct { // Open initialzes necessary variables for using this executor. func (e *TableReaderExecutor) Open(ctx context.Context) error { - span, ctx := startSpanFollowsContext(ctx, "executor.TableReader.Open") - defer span.Finish() - var err error if e.corColInFilter { e.dagPB.Executors, _, err = constructDistExec(e.ctx, e.plans) @@ -101,11 +98,11 @@ func (e *TableReaderExecutor) Open(ctx context.Context) error { // Next fills data into the chunk passed by its caller. // The task was actually done by tableReaderHandler. func (e *TableReaderExecutor) Next(ctx context.Context, chk *chunk.Chunk) error { - err := e.resultHandler.nextChunk(ctx, chk) - if err != nil { + if err := e.resultHandler.nextChunk(ctx, chk); err != nil { e.feedback.Invalidate() + return err } - return errors.Trace(err) + return errors.Trace(nil) } // Close implements the Executor Close interface. @@ -115,7 +112,7 @@ func (e *TableReaderExecutor) Close() error { return errors.Trace(err) } -// buildResp first build request and send it to tikv using distsql.Select. It uses SelectResut returned by the callee +// buildResp first builds request and sends it to tikv using distsql.Select. It uses SelectResut returned by the callee // to fetch all results. func (e *TableReaderExecutor) buildResp(ctx context.Context, ranges []*ranger.Range) (distsql.SelectResult, error) { var builder distsql.RequestBuilder diff --git a/executor/trace.go b/executor/trace.go new file mode 100644 index 0000000000000..23d1cd570e778 --- /dev/null +++ b/executor/trace.go @@ -0,0 +1,131 @@ +// Copyright 2018 PingCAP, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// See the License for the specific language governing permissions and +// limitations under the License. + +package executor + +import ( + "time" + + "github.com/juju/errors" + "github.com/opentracing/basictracer-go" + opentracing "github.com/opentracing/opentracing-go" + "github.com/pingcap/tidb/ast" + "github.com/pingcap/tidb/plan" + "github.com/pingcap/tidb/util/chunk" + "github.com/pingcap/tidb/util/tracing" + "golang.org/x/net/context" +) + +// TraceExec represents a root executor of trace query. +type TraceExec struct { + baseExecutor + // CollectedSpans collects all span during execution. Span is appended via + // callback method which passes into tracer implementation. + CollectedSpans []basictracer.RawSpan + // exhausted being true means there is no more result. + exhausted bool + // stmtNode is the real query ast tree and it is used for building real query's plan. + stmtNode ast.StmtNode + // rootTrace represents root span which is father of all other span. + rootTrace opentracing.Span + + builder *executorBuilder +} + +// Next executes real query and collects span later. +func (e *TraceExec) Next(ctx context.Context, chk *chunk.Chunk) error { + chk.Reset() + if e.exhausted { + return nil + } + + // record how much time was spent for optimizeing plan + optimizeSp := e.rootTrace.Tracer().StartSpan("plan_optimize", opentracing.FollowsFrom(e.rootTrace.Context())) + stmtPlan, err := plan.Optimize(e.builder.ctx, e.stmtNode, e.builder.is) + if err != nil { + return err + } + optimizeSp.Finish() + + pp, ok := stmtPlan.(plan.PhysicalPlan) + if !ok { + return errors.New("cannot cast logical plan to physical plan") + } + + // append select executor to trace executor + stmtExec := e.builder.build(pp) + + e.rootTrace = tracing.NewRecordedTrace("trace_exec", func(sp basictracer.RawSpan) { + e.CollectedSpans = append(e.CollectedSpans, sp) + }) + err = stmtExec.Open(ctx) + if err != nil { + return errors.Trace(err) + } + stmtExecChk := stmtExec.newChunk() + + // store span into context + ctx = opentracing.ContextWithSpan(ctx, e.rootTrace) + + for { + if err := stmtExec.Next(ctx, stmtExecChk); err != nil { + return errors.Trace(err) + } + if stmtExecChk.NumRows() == 0 { + break + } + } + + e.rootTrace.LogKV("event", "tracing completed") + e.rootTrace.Finish() + var rootSpan basictracer.RawSpan + + treeSpans := make(map[uint64][]basictracer.RawSpan) + for _, sp := range e.CollectedSpans { + treeSpans[sp.ParentSpanID] = append(treeSpans[sp.ParentSpanID], sp) + // if a span's parentSpanID is 0, then it is root span + // this is by design + if sp.ParentSpanID == 0 { + rootSpan = sp + } + } + + dfsTree(rootSpan, treeSpans, "", false, chk) + e.exhausted = true + return nil +} + +func dfsTree(span basictracer.RawSpan, tree map[uint64][]basictracer.RawSpan, prefix string, isLast bool, chk *chunk.Chunk) { + suffix := "" + spans := tree[span.Context.SpanID] + var newPrefix string + if span.ParentSpanID == 0 { + newPrefix = prefix + } else { + if len(tree[span.ParentSpanID]) > 0 && !isLast { + suffix = "├─" + newPrefix = prefix + "│ " + } else { + suffix = "└─" + newPrefix = prefix + " " + } + } + + chk.AppendString(0, prefix+suffix+span.Operation) + chk.AppendString(1, span.Start.Format(time.StampNano)) + chk.AppendString(2, span.Duration.String()) + + for i, sp := range spans { + dfsTree(sp, tree, newPrefix, i == (len(spans))-1 /*last element of array*/, chk) + } +} diff --git a/executor/trace_test.go b/executor/trace_test.go new file mode 100644 index 0000000000000..9f8d96f5d8537 --- /dev/null +++ b/executor/trace_test.go @@ -0,0 +1,33 @@ +// Copyright 2018 PingCAP, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// See the License for the specific language governing permissions and +// limitations under the License. + +package executor_test + +import ( + . "github.com/pingcap/check" + "github.com/pingcap/tidb/util/testkit" +) + +type testTraceExec struct{} + +func (s *testTraceExec) SetupSuite(c *C) { +} + +func (s *testSuite) TestTraceExec(c *C) { + tk := testkit.NewTestKit(c, s.store) + tk.MustExec("use test") + testSQL := `create table trace (id int PRIMARY KEY AUTO_INCREMENT, c1 int, c2 int, c3 int default 1);` + tk.MustExec(testSQL) + // TODO: check result later in another PR. + tk.MustExec("trace select * from trace where id = 0;") +} diff --git a/plan/planbuilder.go b/plan/planbuilder.go index ed0e45b36779a..3b64ffcb3f164 100644 --- a/plan/planbuilder.go +++ b/plan/planbuilder.go @@ -141,6 +141,8 @@ func (b *planBuilder) build(node ast.Node) (Plan, error) { return b.buildExecute(x) case *ast.ExplainStmt: return b.buildExplain(x) + case *ast.TraceStmt: + return b.buildTrace(x) case *ast.InsertStmt: return b.buildInsert(x) case *ast.LoadDataStmt: @@ -1359,6 +1361,26 @@ func (b *planBuilder) buildDDL(node ast.DDLNode) Plan { return p } +// buildTrace builds a trace plan. Inside this method, it first optimize the +// underlying query and then constructs a schema, which will be used to constructs +// rows result. +func (b *planBuilder) buildTrace(trace *ast.TraceStmt) (Plan, error) { + if _, ok := trace.Stmt.(*ast.SelectStmt); !ok { + return nil, errors.New("trace only supports select query") + } + + p := &Trace{StmtNode: trace.Stmt} + + retFields := []string{"operation", "duration", "spanID"} + schema := expression.NewSchema(make([]*expression.Column, 0, len(retFields))...) + schema.Append(buildColumn("", "operation", mysql.TypeString, mysql.MaxBlobWidth)) + + schema.Append(buildColumn("", "startTS", mysql.TypeString, mysql.MaxBlobWidth)) + schema.Append(buildColumn("", "duration", mysql.TypeString, mysql.MaxBlobWidth)) + p.SetSchema(schema) + return p, nil +} + func (b *planBuilder) buildExplain(explain *ast.ExplainStmt) (Plan, error) { if show, ok := explain.Stmt.(*ast.ShowStmt); ok { return b.buildShow(show) diff --git a/plan/trace.go b/plan/trace.go new file mode 100644 index 0000000000000..8b08336d7a509 --- /dev/null +++ b/plan/trace.go @@ -0,0 +1,12 @@ +package plan + +import ( + "github.com/pingcap/tidb/ast" +) + +// Trace represents a trace plan. +type Trace struct { + baseSchemaProducer + + StmtNode ast.StmtNode +} diff --git a/session/session.go b/session/session.go index d76313e581abd..11f5641553d9a 100644 --- a/session/session.go +++ b/session/session.go @@ -29,7 +29,6 @@ import ( "github.com/juju/errors" "github.com/ngaut/pools" - "github.com/opentracing/opentracing-go" "github.com/pingcap/tidb/ast" "github.com/pingcap/tidb/domain" "github.com/pingcap/tidb/executor" @@ -375,11 +374,6 @@ func (s *session) doCommitWithRetry(ctx context.Context) error { } func (s *session) CommitTxn(ctx context.Context) error { - if span := opentracing.SpanFromContext(ctx); span != nil { - span = opentracing.StartSpan("session.CommitTxn", opentracing.ChildOf(span.Context())) - defer span.Finish() - } - err := s.doCommitWithRetry(ctx) label := metrics.LblOK if err != nil { @@ -390,11 +384,6 @@ func (s *session) CommitTxn(ctx context.Context) error { } func (s *session) RollbackTxn(ctx context.Context) error { - if span := opentracing.SpanFromContext(ctx); span != nil { - span = opentracing.StartSpan("session.RollbackTxn", opentracing.ChildOf(span.Context())) - defer span.Finish() - } - var err error if s.txn.Valid() { terror.Log(s.txn.Rollback()) @@ -451,9 +440,6 @@ func (s *session) isRetryableError(err error) bool { } func (s *session) retry(ctx context.Context, maxCnt uint) error { - span, ctx := opentracing.StartSpanFromContext(ctx, "retry") - defer span.Finish() - connID := s.sessionVars.ConnectionID if s.sessionVars.TxnCtx.ForUpdate { return errForUpdateCantRetry.GenByArgs(connID) @@ -545,10 +531,7 @@ func (s *session) sysSessionPool() *pools.ResourcePool { // Unlike normal Exec, it doesn't reset statement status, doesn't commit or rollback the current transaction // and doesn't write binlog. func (s *session) ExecRestrictedSQL(sctx sessionctx.Context, sql string) ([]chunk.Row, []*ast.ResultField, error) { - var span opentracing.Span ctx := context.TODO() - span, ctx = opentracing.StartSpanFromContext(ctx, "session.ExecRestrictedSQL") - defer span.Finish() // Use special session to execute the sql. tmp, err := s.sysSessionPool().Get() @@ -712,10 +695,6 @@ func (s *session) SetGlobalSysVar(name, value string) error { } func (s *session) ParseSQL(ctx context.Context, sql, charset, collation string) ([]ast.StmtNode, error) { - if span := opentracing.SpanFromContext(ctx); span != nil { - span1 := opentracing.StartSpan("session.ParseSQL", opentracing.ChildOf(span.Context())) - defer span1.Finish() - } s.parser.SetSQLMode(s.sessionVars.SQLMode) return s.parser.Parse(sql, charset, collation) } @@ -770,11 +749,6 @@ func (s *session) Execute(ctx context.Context, sql string) (recordSets []ast.Rec } func (s *session) execute(ctx context.Context, sql string) (recordSets []ast.RecordSet, err error) { - if span := opentracing.SpanFromContext(ctx); span != nil { - span, ctx = opentracing.StartSpanFromContext(ctx, "session.Execute") - defer span.Finish() - } - s.PrepareTxnCtx(ctx) connID := s.sessionVars.ConnectionID err = s.loadCommonGlobalVariablesIfNeeded() diff --git a/session/tidb.go b/session/tidb.go index df6ce605d2a68..0a50470813ab3 100644 --- a/session/tidb.go +++ b/session/tidb.go @@ -24,7 +24,6 @@ import ( "time" "github.com/juju/errors" - "github.com/opentracing/opentracing-go" "github.com/pingcap/tidb/ast" "github.com/pingcap/tidb/config" "github.com/pingcap/tidb/domain" @@ -143,15 +142,10 @@ func Compile(ctx context.Context, sctx sessionctx.Context, stmtNode ast.StmtNode // runStmt executes the ast.Statement and commit or rollback the current transaction. func runStmt(ctx context.Context, sctx sessionctx.Context, s ast.Statement) (ast.RecordSet, error) { - span, ctx1 := opentracing.StartSpanFromContext(ctx, "runStmt") - span.LogKV("sql", s.OriginText()) - defer span.Finish() - var err error var rs ast.RecordSet se := sctx.(*session) rs, err = s.Exec(ctx) - span.SetTag("txn.id", se.sessionVars.TxnCtx.StartTS) // All the history should be added here. se.GetSessionVars().TxnCtx.StatementCount++ if !s.IsReadOnly() { @@ -169,17 +163,17 @@ func runStmt(ctx context.Context, sctx sessionctx.Context, s ast.Statement) (ast if !se.sessionVars.InTxn() { if err != nil { log.Info("RollbackTxn for ddl/autocommit error.") - err1 := se.RollbackTxn(ctx1) + err1 := se.RollbackTxn(ctx) terror.Log(errors.Trace(err1)) } else { - err = se.CommitTxn(ctx1) + err = se.CommitTxn(ctx) } } else { // If the user insert, insert, insert ... but never commit, TiDB would OOM. // So we limit the statement count in a transaction here. history := GetHistory(sctx) if history.Count() > int(config.GetGlobalConfig().Performance.StmtCountLimit) { - err1 := se.RollbackTxn(ctx1) + err1 := se.RollbackTxn(ctx) terror.Log(errors.Trace(err1)) return rs, errors.Errorf("statement count %d exceeds the transaction limitation, autocommit = %t", history.Count(), sctx.GetSessionVars().IsAutocommit()) diff --git a/session/txn.go b/session/txn.go index 85a64cd77836e..575596b09eb89 100644 --- a/session/txn.go +++ b/session/txn.go @@ -15,7 +15,6 @@ package session import ( "github.com/juju/errors" - "github.com/opentracing/opentracing-go" "github.com/pingcap/tidb/executor" "github.com/pingcap/tidb/kv" "github.com/pingcap/tidb/sessionctx" @@ -232,12 +231,10 @@ func mergeToDirtyDB(dirtyDB *executor.DirtyDB, op dirtyTableOperation) { type txnFuture struct { future oracle.Future store kv.Storage - span opentracing.Span } func (tf *txnFuture) wait() (kv.Transaction, error) { startTS, err := tf.future.Wait() - tf.span.Finish() if err == nil { return tf.store.BeginWithStartTS(startTS) } @@ -247,10 +244,9 @@ func (tf *txnFuture) wait() (kv.Transaction, error) { } func (s *session) getTxnFuture(ctx context.Context) *txnFuture { - span, ctx := opentracing.StartSpanFromContext(ctx, "session.getTxnFuture") oracleStore := s.store.GetOracle() tsFuture := oracleStore.GetTimestampAsync(ctx) - return &txnFuture{tsFuture, s.store, span} + return &txnFuture{tsFuture, s.store} } // StmtCommit implements the sessionctx.Context interface. diff --git a/store/tikv/2pc.go b/store/tikv/2pc.go index 71e5cff4cf114..3fa61f1b405aa 100644 --- a/store/tikv/2pc.go +++ b/store/tikv/2pc.go @@ -21,7 +21,6 @@ import ( "time" "github.com/juju/errors" - "github.com/opentracing/opentracing-go" pb "github.com/pingcap/kvproto/pkg/kvrpcpb" "github.com/pingcap/tidb/kv" "github.com/pingcap/tidb/metrics" @@ -585,20 +584,6 @@ func (c *twoPhaseCommitter) execute(ctx context.Context) error { } }() - span := opentracing.SpanFromContext(ctx) - if span != nil { - span = opentracing.StartSpan("twoPhaseCommit.execute", opentracing.ChildOf(span.Context())) - } else { - // If we lost the trace information, make a new one for 2PC commit. - span = opentracing.StartSpan("twoPhaseCommit.execute") - } - defer span.Finish() - - // I'm not sure is it safe to cancel 2pc commit process at any time, - // So use a new Background() context instead of inherit the ctx, this is by design, - // to avoid the cancel signal from parent context. - ctx = opentracing.ContextWithSpan(context.Background(), span) - binlogChan := c.prewriteBinlog() err := c.prewriteKeys(NewBackoffer(ctx, prewriteMaxBackoff).WithVars(c.txn.vars), c.keys) if binlogChan != nil { diff --git a/store/tikv/backoff.go b/store/tikv/backoff.go index 80d8b9ee29207..3a55218aef451 100644 --- a/store/tikv/backoff.go +++ b/store/tikv/backoff.go @@ -225,7 +225,7 @@ func (b *Backoffer) Backoff(typ backoffType, err error) error { b.totalSleep += f(b.ctx) b.types = append(b.types, typ) - log.Debugf("%v, retry later(totalSleep %dms, maxSleep %dms)", err, b.totalSleep, b.maxSleep) + log.Debugf("%v, retry later(totalsleep %dms, maxsleep %dms)", err, b.totalSleep, b.maxSleep) b.errors = append(b.errors, errors.Errorf("%s at %s", err.Error(), time.Now().Format(time.RFC3339Nano))) if b.maxSleep > 0 && b.totalSleep >= b.maxSleep { diff --git a/store/tikv/coprocessor.go b/store/tikv/coprocessor.go index e5f15c148a283..34153fb9b60f1 100644 --- a/store/tikv/coprocessor.go +++ b/store/tikv/coprocessor.go @@ -25,7 +25,6 @@ import ( "github.com/cznic/mathutil" "github.com/juju/errors" - "github.com/opentracing/opentracing-go" "github.com/pingcap/kvproto/pkg/coprocessor" "github.com/pingcap/kvproto/pkg/kvrpcpb" "github.com/pingcap/tidb/kv" @@ -417,11 +416,6 @@ const minLogCopTaskTime = 300 * time.Millisecond // run is a worker function that get a copTask from channel, handle it and // send the result back. func (worker *copIteratorWorker) run(ctx context.Context) { - if span := opentracing.SpanFromContext(ctx); span != nil { - span, ctx = opentracing.StartSpanFromContext(ctx, "copIteratorWorker.run") - defer span.Finish() - } - defer worker.wg.Done() for task := range worker.taskCh { respCh := worker.respChan diff --git a/util/tracing/noop_bench_test.go b/util/tracing/noop_bench_test.go new file mode 100644 index 0000000000000..76b940231c195 --- /dev/null +++ b/util/tracing/noop_bench_test.go @@ -0,0 +1,53 @@ +// Copyright 2018 PingCAP, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// See the License for the specific language governing permissions and +// limitations under the License. + +package tracing + +import ( + "context" + "fmt" + "testing" +) + +// BenchmarkNoopLogKV benchs the cost of noop's `LogKV`. +func BenchmarkNoopLogKV(b *testing.B) { + sp := noopSpan() + for i := 0; i < b.N; i++ { + sp.LogKV("event", "noop is finished") + } +} + +// BenchmarkNoopLogKVWithF benchs the the cosst of noop's `LogKV` when +// used with `fmt.Sprintf` +func BenchmarkNoopLogKVWithF(b *testing.B) { + sp := noopSpan() + for i := 0; i < b.N; i++ { + sp.LogKV("event", fmt.Sprintf("this is format %s", "noop is finished")) + } +} + +// BenchmarkSpanFromContext benchs the cost of `SpanFromContext`. +func BenchmarkSpanFromContext(b *testing.B) { + ctx := context.TODO() + for i := 0; i < b.N; i++ { + SpanFromContext(ctx) + } +} + +// BenchmarkChildFromContext benchs the cost of `ChildSpanFromContxt`. +func BenchmarkChildFromContext(b *testing.B) { + ctx := context.TODO() + for i := 0; i < b.N; i++ { + ChildSpanFromContxt(ctx, "child") + } +} diff --git a/util/tracing/util.go b/util/tracing/util.go new file mode 100644 index 0000000000000..f22be09d6f67d --- /dev/null +++ b/util/tracing/util.go @@ -0,0 +1,66 @@ +// Copyright 2018 PingCAP, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// See the License for the specific language governing permissions and +// limitations under the License. + +package tracing + +import ( + "github.com/opentracing/basictracer-go" + "github.com/opentracing/opentracing-go" + "golang.org/x/net/context" +) + +// TiDBTrace is set as Baggage on traces which are used for tidb tracing. +const TiDBTrace = "tr" + +// A CallbackRecorder immediately invokes itself on received trace spans. +type CallbackRecorder func(sp basictracer.RawSpan) + +// RecordSpan implements basictracer.SpanRecorder. +func (cr CallbackRecorder) RecordSpan(sp basictracer.RawSpan) { + cr(sp) +} + +// NewRecordedTrace returns a Span which records directly via the specified +// callback. +func NewRecordedTrace(opName string, callback func(sp basictracer.RawSpan)) opentracing.Span { + tr := basictracer.New(CallbackRecorder(callback)) + opentracing.SetGlobalTracer(tr) + sp := tr.StartSpan(opName) + sp.SetBaggageItem(TiDBTrace, "1") + return sp +} + +// noopSpan returns a Span which discards all operations. +func noopSpan() opentracing.Span { + return (opentracing.NoopTracer{}).StartSpan("DefaultSpan") +} + +// SpanFromContext returns the span obtained from the context or, if none is found, a new one started through tracer. +func SpanFromContext(ctx context.Context) (sp opentracing.Span) { + if sp = opentracing.SpanFromContext(ctx); sp == nil { + return noopSpan() + } + return sp +} + +// ChildSpanFromContxt return a non-nil span. If span can be got from ctx, then returned span is +// a child of such span. Otherwise, returned span is a noop span. +func ChildSpanFromContxt(ctx context.Context, opName string) (opentracing.Span, context.Context) { + if sp := opentracing.SpanFromContext(ctx); sp != nil { + if _, ok := sp.Tracer().(opentracing.NoopTracer); !ok { + child := opentracing.StartSpan(opName, opentracing.ChildOf(sp.Context())) + return child, opentracing.ContextWithSpan(ctx, child) + } + } + return noopSpan(), ctx +} diff --git a/util/tracing/util_test.go b/util/tracing/util_test.go new file mode 100644 index 0000000000000..4cbac84f1aaa6 --- /dev/null +++ b/util/tracing/util_test.go @@ -0,0 +1,142 @@ +// Copyright 2018 PingCAP, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// See the License for the specific language governing permissions and +// limitations under the License. + +package tracing_test + +import ( + "testing" + + . "github.com/pingcap/check" + + basictracer "github.com/opentracing/basictracer-go" + "github.com/opentracing/opentracing-go" + "github.com/pingcap/tidb/util/tracing" + "golang.org/x/net/context" +) + +var _ = Suite(&testTraceSuite{}) + +func TestT(t *testing.T) { + TestingT(t) +} + +type testTraceSuite struct { +} + +func (s *testTraceSuite) TestSpanFromContext(c *C) { + ctx := context.TODO() + noopSp := tracing.SpanFromContext(ctx) + // test noop span + _, ok := noopSp.Tracer().(opentracing.NoopTracer) + c.Assert(ok, IsTrue) + + // test tidb tracing + collectedSpan := make([]basictracer.RawSpan, 1) + sp := tracing.NewRecordedTrace("test", func(sp basictracer.RawSpan) { + collectedSpan = append(collectedSpan, sp) + }) + sp.Finish() + opentracing.ContextWithSpan(ctx, sp) + child := tracing.SpanFromContext(ctx) + child.Finish() + + // verify second span's operation is not nil, this way we can ensure + // callback logic works. + c.Assert(collectedSpan[0].Operation, NotNil) +} + +func (s *testTraceSuite) TestChildSpanFromContext(c *C) { + ctx := context.TODO() + noopSp, _ := tracing.ChildSpanFromContxt(ctx, "") + _, ok := noopSp.Tracer().(opentracing.NoopTracer) + c.Assert(ok, IsTrue) + + // test tidb tracing + collectedSpan := make([]basictracer.RawSpan, 1) + sp := tracing.NewRecordedTrace("test", func(sp basictracer.RawSpan) { + collectedSpan = append(collectedSpan, sp) + }) + sp.Finish() + opentracing.ContextWithSpan(ctx, sp) + child, _ := tracing.ChildSpanFromContxt(ctx, "test_child") + child.Finish() + + // verify second span's operation is not nil, this way we can ensure + // callback logic works. + c.Assert(collectedSpan[1].Operation, NotNil) + +} + +func (s *testTraceSuite) TestFollowFrom(c *C) { + var collectedSpans []basictracer.RawSpan + // first start a root span + sp1 := tracing.NewRecordedTrace("test", func(sp basictracer.RawSpan) { + collectedSpans = append(collectedSpans, sp) + }) + sp2 := sp1.Tracer().StartSpan("follow_from", opentracing.FollowsFrom(sp1.Context())) + sp1.Finish() + sp2.Finish() + c.Assert(collectedSpans[1].Operation, Equals, "follow_from") + c.Assert(collectedSpans[1].ParentSpanID, Not(Equals), uint64(0)) + // only root span has 0 parent id + c.Assert(collectedSpans[0].ParentSpanID, Equals, uint64(0)) +} + +func (s *testTraceSuite) TestCreateSapnBeforeSetupGlobalTracer(c *C) { + var collectedSpans []basictracer.RawSpan + sp := opentracing.StartSpan("before") + sp.Finish() + + // first start a root span + sp1 := tracing.NewRecordedTrace("test", func(sp basictracer.RawSpan) { + collectedSpans = append(collectedSpans, sp) + }) + sp1.Finish() + + // sp is a span started before we setup global tracer; hence such span will be + // droped. + c.Assert(len(collectedSpans), Equals, 1) +} + +func (s *testTraceSuite) TestTreeRelationship(c *C) { + var collectedSpans []basictracer.RawSpan + ctx := context.TODO() + // first start a root span + sp1 := tracing.NewRecordedTrace("test", func(sp basictracer.RawSpan) { + collectedSpans = append(collectedSpans, sp) + }) + + // then store such root span into context + ctx = opentracing.ContextWithSpan(ctx, sp1) + + // create children span from context + sp2, ctx := tracing.ChildSpanFromContxt(ctx, "parent") + sp3, _ := tracing.ChildSpanFromContxt(ctx, "child") + + // notify span that we are about to reach end of journey. + sp1.Finish() + sp2.Finish() + sp3.Finish() + + // ensure length of collectedSpans is greather than 0 + c.Assert(len(collectedSpans), Greater, 0) + if len(collectedSpans) > 0 { + c.Assert(collectedSpans[0].Operation, Equals, "test") + c.Assert(collectedSpans[1].Operation, Equals, "parent") + c.Assert(collectedSpans[2].Operation, Equals, "child") + // check tree relationship + // sp1 is parent of sp2. And sp2 is parent of sp3. + c.Assert(collectedSpans[1].ParentSpanID, Equals, collectedSpans[0].Context.SpanID) + c.Assert(collectedSpans[2].ParentSpanID, Equals, collectedSpans[1].Context.SpanID) + } +}