diff --git a/docs/api.asciidoc b/docs/api.asciidoc index ccba81a29..bbc7625fc 100644 --- a/docs/api.asciidoc +++ b/docs/api.asciidoc @@ -100,20 +100,20 @@ application. StartSpan starts and returns a new Span within the transaction, with the specified name, type, and optional parent span, and with the start time set to the current time relative -to the transaction's timestamp. The span's ID will be set. +to the transaction's timestamp. If the transaction is sampled, then the span's ID will be set, and its stacktrace will -be set if the tracer is configured accordingly. +be set if the tracer is configured accordingly. If the transaction is not sampled, then +the returned span will be silently discarded when its Done method is called. You can +avoid any unnecessary computation for these dropped spans by calling its <> +method. -IMPORTANT: If the transaction is not being sampled, then StartSpan will return nil. -You should always check if the resulting span is nil before using it. +As a convenience, it is valid to create a span on a nil Transaction; the resulting span +will be non-nil and safe for use, but will not be reported to the APM server. [source,go] ---- span := tx.StartSpan("SELECT FROM foo", "db.mysql.query", nil) -if span != nil { - ... -} ---- [float] @@ -121,16 +121,12 @@ if span != nil { ==== `func StartSpan(ctx context.Context, name, spanType string) (*Span, context.Context)` StartSpan starts and returns a new Span within the sampled transaction and parent span -in the context, if any, and returns the span along with a new context containing the span. - -If there is no transaction in the context, or it is not being sampled, StartSpan returns nil. +in the context, if any. If the span isn't dropped, it will be indluded in the resulting +context. [source,go] ---- span, ctx := elasticapm.StartSpan(ctx, "SELECT FROM foo", "db.mysql.query") -if span != nil { - ... -} ---- [float] @@ -142,6 +138,14 @@ Done sets the span's duration to the specified value. The Span must not be used If the duration specified is negative, then Done will set the duration to the amount of wall-clock time that has elapsed since the span was started. +[float] +[[span-dropped]] +==== `func (*Span) Dropped() bool` + +Dropped indicates whether or not the span is dropped, meaning it will not be reported to +the APM server. Spans are dropped when the created via a nil or non-sampled transaction, +or one whose max spans limit has been reached. + // ------------------------------------------------------------------------------------------------- [float] diff --git a/docs/instrumenting.asciidoc b/docs/instrumenting.asciidoc index 03c664dbb..8cfaab30d 100644 --- a/docs/instrumenting.asciidoc +++ b/docs/instrumenting.asciidoc @@ -284,17 +284,13 @@ contains a span, then that will be considered the parent. [source,go] ---- span, ctx := elasticapm.StartSpan(ctx, "SELECT FROM foo", "db.mysql.query") -if span != nil { - defer span.Done(-1) -} +defer span.Done(-1) ---- -Note that both `Transaction.StartSpan` and `elasticapm.StartSpan` will return a nil `Span` if the transaction -is not being sampled. By default, all transactions are sampled; that is, all transactions are sent with -complete detail to the Elastic APM server. If you configure the agent to sample transactions at less than -100%, then spans and context will be dropped, and in this case, StartSpan will sometimes return nil. Since -sampling on the tracer can be configured via an environment variable <>, -it is a good idea to always check for a nil result. +`Transaction.StartSpan` and `elasticapm.StartSpan` will always return a non-nil `Span`, even if the +transaction is nil. It is always safe to defer a call to the span's Done method. If setting the span's +context would incur significant overhead, you may want to check if the span is dropped first, by calling +the `Span.Dropped` method. ===== Panic recovery and errors diff --git a/example_test.go b/example_test.go index db05e60d0..95abeb340 100644 --- a/example_test.go +++ b/example_test.go @@ -118,9 +118,7 @@ func (api *api) handleOrder(ctx context.Context, product string) { func storeOrder(ctx context.Context, product string) { span, _ := elasticapm.StartSpan(ctx, "store_order", "rpc") - if span != nil { - defer span.Done(-1) - } + defer span.Done(-1) time.Sleep(50 * time.Millisecond) } diff --git a/gocontext.go b/gocontext.go index 7b49ce4c8..c4c4ded7c 100644 --- a/gocontext.go +++ b/gocontext.go @@ -31,18 +31,18 @@ func TransactionFromContext(ctx context.Context) *Transaction { } // StartSpan starts and returns a new Span within the sampled transaction -// and parent span in the context, if any, and returns the span along with -// a new context containing the span. +// and parent span in the context, if any. If the span isn't dropped, it +// will be stored in the resulting context. // -// If there is no transaction in the context, or it is not being sampled, -// StartSpan returns nil. +// StartSpan always returns a non-nil Span. Its Done method must be called +// when the span completes. func StartSpan(ctx context.Context, name, spanType string) (*Span, context.Context) { tx := TransactionFromContext(ctx) - if tx == nil || !tx.Sampled() { - return nil, ctx - } span := tx.StartSpan(name, spanType, SpanFromContext(ctx)) - return span, context.WithValue(ctx, contextSpanKey{}, span) + if !span.Dropped() { + ctx = context.WithValue(ctx, contextSpanKey{}, span) + } + return span, ctx } // CaptureError returns a new Error related to the sampled transaction diff --git a/gofuzz.go b/gofuzz.go index 1269b02aa..14a258965 100644 --- a/gofuzz.go +++ b/gofuzz.go @@ -133,18 +133,16 @@ func Fuzz(data []byte) int { continue } span := tx.StartSpan(s.Name, s.Type, nil) - if span != nil { - span.Start = tx.Timestamp.Add(time.Duration(s.Start * float64(time.Millisecond))) - if s.Context != nil && s.Context.Database != nil { - span.Context.SetDatabase(DatabaseSpanContext{ - Instance: s.Context.Database.Instance, - Statement: s.Context.Database.Statement, - Type: s.Context.Database.Type, - User: s.Context.Database.User, - }) - } - span.Done(time.Duration(s.Duration * float64(time.Millisecond))) + span.Start = tx.Timestamp.Add(time.Duration(s.Start * float64(time.Millisecond))) + if s.Context != nil && s.Context.Database != nil { + span.Context.SetDatabase(DatabaseSpanContext{ + Instance: s.Context.Database.Instance, + Statement: s.Context.Database.Statement, + Type: s.Context.Database.Type, + User: s.Context.Database.User, + }) } + span.Done(time.Duration(s.Duration * float64(time.Millisecond))) } tx.Done(time.Duration(t.Duration * float64(time.Millisecond))) } diff --git a/module/apmgrpc/client.go b/module/apmgrpc/client.go index 9e1336b82..3bb7f988a 100644 --- a/module/apmgrpc/client.go +++ b/module/apmgrpc/client.go @@ -27,9 +27,7 @@ func NewUnaryClientInterceptor(o ...ClientOption) grpc.UnaryClientInterceptor { opts ...grpc.CallOption, ) error { span, ctx := elasticapm.StartSpan(ctx, method, "grpc") - if span != nil { - defer span.Done(-1) - } + defer span.Done(-1) return invoker(ctx, method, req, resp, cc, opts...) } } diff --git a/module/apmgrpc/server_test.go b/module/apmgrpc/server_test.go index dc9babf3a..e2feae273 100644 --- a/module/apmgrpc/server_test.go +++ b/module/apmgrpc/server_test.go @@ -203,9 +203,7 @@ func (s *helloworldServer) SayHello(ctx context.Context, req *pb.HelloRequest) ( // The context passed to the server should contain a Transaction // for the gRPC request. span, ctx := elasticapm.StartSpan(ctx, "server_span", "type") - if span != nil { - span.Done(-1) - } + span.Done(-1) if s.panic { panic(s.err) } diff --git a/module/apmsql/apmsql_bench_test.go b/module/apmsql/apmsql_bench_test.go index 10566a7f1..76386d0f6 100644 --- a/module/apmsql/apmsql_bench_test.go +++ b/module/apmsql/apmsql_bench_test.go @@ -36,6 +36,7 @@ func BenchmarkStmtQueryContext(b *testing.B) { tracer.Transport = httpTransport defer tracer.Close() + tracer.SetMaxSpans(b.N) tx := tracer.StartTransaction("name", "type") ctx := elasticapm.ContextWithTransaction(context.Background(), tx) benchmarkQueries(b, ctx, stmt) diff --git a/module/apmsql/conn.go b/module/apmsql/conn.go index e0fc2935b..982be8847 100644 --- a/module/apmsql/conn.go +++ b/module/apmsql/conn.go @@ -46,7 +46,7 @@ func (c *conn) startStmtSpan(ctx context.Context, stmt, spanType string) (*elast func (c *conn) startSpan(ctx context.Context, name, spanType, stmt string) (*elasticapm.Span, context.Context) { span, ctx := elasticapm.StartSpan(ctx, name, spanType) - if span != nil { + if !span.Dropped() { span.Context.SetDatabase(elasticapm.DatabaseSpanContext{ Instance: c.dsnInfo.Database, Statement: stmt, @@ -77,9 +77,7 @@ func (c *conn) Ping(ctx context.Context) (resultError error) { return nil } span, ctx := c.startSpan(ctx, "ping", c.driver.pingSpanType, "") - if span != nil { - defer c.finishSpan(ctx, span, resultError) - } + defer c.finishSpan(ctx, span, resultError) return c.pinger.Ping(ctx) } @@ -88,9 +86,7 @@ func (c *conn) QueryContext(ctx context.Context, query string, args []driver.Nam return nil, driver.ErrSkip } span, ctx := c.startStmtSpan(ctx, query, c.driver.querySpanType) - if span != nil { - defer c.finishSpan(ctx, span, resultError) - } + defer c.finishSpan(ctx, span, resultError) if c.queryerContext != nil { return c.queryerContext.QueryContext(ctx, query, args) @@ -113,9 +109,7 @@ func (*conn) Query(query string, args []driver.Value) (driver.Rows, error) { func (c *conn) PrepareContext(ctx context.Context, query string) (_ driver.Stmt, resultError error) { span, ctx := c.startStmtSpan(ctx, query, c.driver.prepareSpanType) - if span != nil { - defer c.finishSpan(ctx, span, resultError) - } + defer c.finishSpan(ctx, span, resultError) var stmt driver.Stmt var err error if c.connPrepareContext != nil { @@ -142,9 +136,7 @@ func (c *conn) ExecContext(ctx context.Context, query string, args []driver.Name return nil, driver.ErrSkip } span, ctx := c.startStmtSpan(ctx, query, c.driver.execSpanType) - if span != nil { - defer c.finishSpan(ctx, span, resultError) - } + defer c.finishSpan(ctx, span, resultError) if c.execerContext != nil { return c.execerContext.ExecContext(ctx, query, args) diff --git a/module/apmsql/driver_go110.go b/module/apmsql/driver_go110.go index f9b34736d..947d0bccb 100644 --- a/module/apmsql/driver_go110.go +++ b/module/apmsql/driver_go110.go @@ -31,11 +31,9 @@ type driverConnector struct { func (d *driverConnector) Connect(ctx context.Context) (driver.Conn, error) { span, ctx := elasticapm.StartSpan(ctx, "connect", d.driver.connectSpanType) - if span != nil { - defer span.Done(-1) - } + defer span.Done(-1) dsnInfo := d.driver.dsnParser(d.name) - if span != nil { + if !span.Dropped() { span.Context.SetDatabase(elasticapm.DatabaseSpanContext{ Instance: dsnInfo.Database, Type: "sql", diff --git a/module/apmsql/stmt.go b/module/apmsql/stmt.go index 23629cd6e..f286b5d3e 100644 --- a/module/apmsql/stmt.go +++ b/module/apmsql/stmt.go @@ -46,9 +46,7 @@ func (s *stmt) ColumnConverter(idx int) driver.ValueConverter { func (s *stmt) ExecContext(ctx context.Context, args []driver.NamedValue) (_ driver.Result, resultError error) { span, ctx := s.startSpan(ctx, s.conn.driver.execSpanType) - if span != nil { - defer s.conn.finishSpan(ctx, span, resultError) - } + defer s.conn.finishSpan(ctx, span, resultError) if s.stmtExecContext != nil { return s.stmtExecContext.ExecContext(ctx, args) } @@ -66,9 +64,7 @@ func (s *stmt) ExecContext(ctx context.Context, args []driver.NamedValue) (_ dri func (s *stmt) QueryContext(ctx context.Context, args []driver.NamedValue) (_ driver.Rows, resultError error) { span, ctx := s.startSpan(ctx, s.conn.driver.querySpanType) - if span != nil { - defer s.conn.finishSpan(ctx, span, resultError) - } + defer s.conn.finishSpan(ctx, span, resultError) if s.stmtQueryContext != nil { return s.stmtQueryContext.QueryContext(ctx, args) } diff --git a/transaction.go b/transaction.go index 2fd99d611..ed424f48a 100644 --- a/transaction.go +++ b/transaction.go @@ -8,6 +8,11 @@ import ( "github.com/elastic/apm-agent-go/stacktrace" ) +// droppedSpanPool holds *Spans which are used when the span +// is created for a nil or non-sampled Transaction, or one +// whose max spans limit has been reached. +var droppedSpanPool sync.Pool + // StartTransaction returns a new Transaction with the specified // name and type, and with the start time set to the current time. func (t *Tracer) StartTransaction(name, transactionType string) *Transaction { @@ -165,7 +170,7 @@ func (tx *Transaction) Done(d time.Duration) { if len(spans) != 0 { tx.model.Spans = make([]*model.Span, len(spans)) for i, s := range spans { - s.truncate(d) + s.finalize(tx.Timestamp.Add(d)) tx.model.Spans[i] = &s.model } } @@ -189,58 +194,58 @@ func (tx *Transaction) enqueue() { // StartSpan starts and returns a new Span within the transaction, // with the specified name, type, and optional parent span, and // with the start time set to the current time relative to the -// transaction's timestamp. The span's ID will be set. -// -// If the transaction is not being sampled, then StartSpan will -// return nil. +// transaction's timestamp. // -// If the transaction is sampled, then the span's ID will be set, -// and its stacktrace will be set if the tracer is configured -// accordingly. +// StartSpan always returns a non-nil Span. Its Done method must +// be called when the span completes. func (tx *Transaction) StartSpan(name, spanType string, parent *Span) *Span { - if !tx.Sampled() { - return nil + if tx == nil || !tx.Sampled() { + return newDroppedSpan() } - start := time.Now() - span, _ := tx.tracer.spanPool.Get().(*Span) + var span *Span + tx.mu.Lock() + if tx.maxSpans > 0 && len(tx.spans) >= tx.maxSpans { + tx.model.SpanCount.Dropped.Total++ + tx.mu.Unlock() + return newDroppedSpan() + } + span, _ = tx.tracer.spanPool.Get().(*Span) if span == nil { span = &Span{} } span.tx = tx + span.id = int64(len(tx.spans)) + tx.spans = append(tx.spans, span) + tx.mu.Unlock() + span.model.Name = truncateString(name) span.model.Type = truncateString(spanType) - span.Start = start - - tx.mu.Lock() - if tx.maxSpans > 0 && len(tx.spans) >= tx.maxSpans { - span.dropped = true - tx.model.SpanCount.Dropped.Total++ - } else { - if parent != nil { - span.model.Parent = parent.model.ID - } - spanID := int64(len(tx.spans)) - span.model.ID = &spanID - tx.spans = append(tx.spans, span) + span.Start = time.Now() + if parent != nil { + span.model.Parent = parent.model.ID } - tx.mu.Unlock() return span } // Span describes an operation within a transaction. type Span struct { - model model.Span + tx *Transaction // nil if span is dropped + id int64 Start time.Time Context SpanContext + mu sync.Mutex + model model.Span stacktrace []stacktrace.Frame - tx *Transaction - dropped bool +} - mu sync.Mutex - done bool - truncated bool +func newDroppedSpan() *Span { + span, _ := droppedSpanPool.Get().(*Span) + if span == nil { + span = &Span{} + } + return span } func (s *Span) reset() { @@ -257,8 +262,6 @@ func (s *Span) reset() { // SetStacktrace sets the stacktrace for the span, // skipping the first skip number of frames, // excluding the SetStacktrace function. -// -// If the span is dropped, this method is a no-op. func (s *Span) SetStacktrace(skip int) { if s.Dropped() { return @@ -267,11 +270,15 @@ func (s *Span) SetStacktrace(skip int) { s.model.Stacktrace = appendModelStacktraceFrames(s.model.Stacktrace[:0], s.stacktrace) } -// Dropped indicates whether or not the span is dropped, meaning it -// will not be included in the transaction. Spans are dropped when -// the configurable limit is reached. +// Dropped indicates whether or not the span is dropped, meaning it will not +// be included in any transaction. Spans are dropped by Transaction.StartSpan +// if the transaction is nil, non-sampled, or the transaction's max spans +// limit has been reached. +// +// Dropped may be used to avoid any expensive computation required to set +// the span's context. func (s *Span) Dropped() bool { - return s.dropped + return s.tx == nil } // Done sets the span's duration to the specified value. The Span @@ -279,34 +286,36 @@ func (s *Span) Dropped() bool { // // If the duration specified is negative, then Done will set the // duration to "time.Since(s.Start)" instead. -// -// If the span is dropped, this method is a no-op. func (s *Span) Done(d time.Duration) { if s.Dropped() { + droppedSpanPool.Put(s) return } if d < 0 { d = time.Since(s.Start) } s.mu.Lock() - s.model.Start = s.Start.Sub(s.tx.Timestamp).Seconds() * 1000 - s.model.Context = s.Context.build() - if s.model.Stacktrace == nil && d >= s.tx.spanFramesMinDuration { - s.SetStacktrace(1) - } - if !s.truncated { - s.done = true + if s.model.ID == nil { + s.model.ID = &s.id s.model.Duration = d.Seconds() * 1000 + if s.model.Stacktrace == nil && d >= s.tx.spanFramesMinDuration { + s.SetStacktrace(1) + } } s.mu.Unlock() } -func (s *Span) truncate(d time.Duration) { +func (s *Span) finalize(end time.Time) { + s.model.Start = s.Start.Sub(s.tx.Timestamp).Seconds() * 1000 + s.model.Context = s.Context.build() + s.mu.Lock() - if !s.done { - s.truncated = true + if s.model.ID == nil { + // s.Done was never called, so mark it as truncated and + // truncate its duration to the end of the transaction. + s.model.ID = &s.id s.model.Type += ".truncated" - s.model.Duration = d.Seconds() * 1000 + s.model.Duration = end.Sub(s.Start).Seconds() * 1000 } s.mu.Unlock() }