diff --git a/operation_name_go124.go b/operation_name_go124.go index 98726ed..efe7b96 100644 --- a/operation_name_go124.go +++ b/operation_name_go124.go @@ -7,13 +7,9 @@ import ( "strings" ) -// sqlOperationName attempts to get the first 'word' from a given SQL query, which usually +// defaultSpanNameFunc attempts to get the first 'word' from a given SQL query, which usually // is the operation name (e.g. 'SELECT'). -func (t *Tracer) sqlOperationName(stmt string) string { - if t.spanNameFunc != nil { - return t.spanNameFunc(stmt) - } - +func defaultSpanNameFunc(stmt string) string { for word := range strings.FieldsSeq(stmt) { return strings.ToUpper(word) } diff --git a/operation_name_legacy.go b/operation_name_legacy.go index 45442e2..20338b8 100644 --- a/operation_name_legacy.go +++ b/operation_name_legacy.go @@ -8,16 +8,9 @@ import ( "unicode" ) -// sqlOperationName attempts to get the first 'word' from a given SQL query, which usually +// defaultSpanNameFunc attempts to get the first 'word' from a given SQL query, which usually // is the operation name (e.g. 'SELECT'). -func (t *Tracer) sqlOperationName(stmt string) string { - // If a custom function is provided, use that. Otherwise, fall back to the - // default implementation. This allows users to override the default - // behavior without having to reimplement it. - if t.spanNameFunc != nil { - return t.spanNameFunc(stmt) - } - +func defaultSpanNameFunc(stmt string) string { stmt = strings.TrimSpace(stmt) end := strings.IndexFunc(stmt, unicode.IsSpace) if end < 0 && len(stmt) > 0 { diff --git a/tracer.go b/tracer.go index d70b91d..6838069 100644 --- a/tracer.go +++ b/tracer.go @@ -6,6 +6,7 @@ import ( "errors" "fmt" "runtime/debug" + "sync" "time" "github.com/jackc/pgx/v5" @@ -20,9 +21,11 @@ import ( ) const ( - tracerName = "github.com/exaring/otelpgx" - meterName = "github.com/exaring/otelpgx" - startTimeCtxKey = "otelpgxStartTime" + tracerName = "github.com/exaring/otelpgx" + meterName = "github.com/exaring/otelpgx" +) + +const ( sqlOperationUnknown = "UNKNOWN" ) @@ -51,16 +54,23 @@ const ( DBClientOperationErrorsKey = attribute.Key("db.client.operation.errors") ) +type startTimeCtxKey struct{} + var _ pgxpool.AcquireTracer = (*Tracer)(nil) // Tracer is a wrapper around the pgx tracer interfaces which instrument // queries with both tracing and metrics. +// Use [NewTracer] to create a new instance. type Tracer struct { tracer trace.Tracer meter metric.Meter tracerAttrs []attribute.KeyValue meterAttrs []attribute.KeyValue + spanStartOptionsPool sync.Pool + attributeSlicePool sync.Pool + metricAttrs map[string]attribute.Set + operationDuration metric.Int64Histogram operationErrors metric.Int64Counter @@ -99,7 +109,7 @@ func NewTracer(opts ...Option) *Tracer { semconv.DBSystemPostgreSQL, }, trimQuerySpanName: false, - spanNameFunc: nil, + spanNameFunc: defaultSpanNameFunc, prefixQuerySpanName: true, logSQLStatement: true, logConnectionDetails: true, @@ -111,8 +121,20 @@ func NewTracer(opts ...Option) *Tracer { } tracer := &Tracer{ - tracer: cfg.tracerProvider.Tracer(tracerName, trace.WithInstrumentationVersion(findOwnImportedVersion())), - meter: cfg.meterProvider.Meter(meterName, metric.WithInstrumentationVersion(findOwnImportedVersion())), + tracer: cfg.tracerProvider.Tracer(tracerName, trace.WithInstrumentationVersion(findOwnImportedVersion())), + meter: cfg.meterProvider.Meter(meterName, metric.WithInstrumentationVersion(findOwnImportedVersion())), + spanStartOptionsPool: sync.Pool{ + New: func() any { + s := make([]trace.SpanStartOption, 0, 10) + return &s + }, + }, + attributeSlicePool: sync.Pool{ + New: func() any { + s := make([]attribute.KeyValue, 0, 10) + return &s + }, + }, tracerAttrs: cfg.tracerAttrs, meterAttrs: cfg.meterAttrs, trimQuerySpanName: cfg.trimQuerySpanName, @@ -123,6 +145,7 @@ func NewTracer(opts ...Option) *Tracer { } tracer.createMetrics() + tracer.createAttributeSets() return tracer } @@ -150,6 +173,22 @@ func (t *Tracer) createMetrics() { } } +func (t *Tracer) createAttributeSets() { + t.metricAttrs = make(map[string]attribute.Set) + operations := []string{ + pgxOperationQuery, + pgxOperationCopy, + pgxOperationBatch, + pgxOperationConnect, + pgxOperationPrepare, + pgxOperationAcquire, + } + for _, op := range operations { + attrs := append(t.meterAttrs, PGXOperationTypeKey.String(op)) + t.metricAttrs[op] = attribute.NewSet(attrs...) + } +} + // recordSpanError handles all error handling to be applied on the provided span. // The provided error must be non-nil and not a sql.ErrNoRows error. // Otherwise, recordSpanError will be a no-op. @@ -170,31 +209,31 @@ func recordSpanError(span trace.Span, err error) { func (t *Tracer) incrementOperationErrorCount(ctx context.Context, err error, pgxOperation string) { if err != nil && !errors.Is(err, sql.ErrNoRows) { t.operationErrors.Add(ctx, 1, metric.WithAttributeSet( - attribute.NewSet(append(t.meterAttrs, PGXOperationTypeKey.String(pgxOperation))...), + t.metricAttrs[pgxOperation], )) } } // recordOperationDuration will compute and record the time since the start of an operation. func (t *Tracer) recordOperationDuration(ctx context.Context, pgxOperation string) { - if startTime, ok := ctx.Value(startTimeCtxKey).(time.Time); ok { + if startTime, ok := ctx.Value(startTimeCtxKey{}).(time.Time); ok { t.operationDuration.Record(ctx, time.Since(startTime).Milliseconds(), metric.WithAttributeSet( - attribute.NewSet(append(t.meterAttrs, PGXOperationTypeKey.String(pgxOperation))...), + t.metricAttrs[pgxOperation], )) } } // connectionAttributesFromConfig returns a SpanStartOption that contains // attributes from the given connection config. -func connectionAttributesFromConfig(config *pgx.ConnConfig) trace.SpanStartOption { +func connectionAttributesFromConfig(config *pgx.ConnConfig) []attribute.KeyValue { if config != nil { - return trace.WithAttributes( + return []attribute.KeyValue{ semconv.DBSystemPostgreSQL, semconv.ServerAddress(config.Host), semconv.ServerPort(int(config.Port)), semconv.UserName(config.User), semconv.DBNamespace(config.Database), - ) + } } return nil } @@ -202,36 +241,46 @@ func connectionAttributesFromConfig(config *pgx.ConnConfig) trace.SpanStartOptio // TraceQueryStart is called at the beginning of Query, QueryRow, and Exec calls. // The returned context is used for the rest of the call and will be passed to TraceQueryEnd. func (t *Tracer) TraceQueryStart(ctx context.Context, conn *pgx.Conn, data pgx.TraceQueryStartData) context.Context { - ctx = context.WithValue(ctx, startTimeCtxKey, time.Now()) + ctx = context.WithValue(ctx, startTimeCtxKey{}, time.Now()) if !trace.SpanFromContext(ctx).IsRecording() { return ctx } - opts := make([]trace.SpanStartOption, 0, 6) - opts = append(opts, - trace.WithSpanKind(trace.SpanKindClient), - trace.WithAttributes(t.tracerAttrs...), - ) + optsP := t.spanStartOptionsPool.Get().(*[]trace.SpanStartOption) + defer t.spanStartOptionsPool.Put(optsP) + attrsP := t.attributeSlicePool.Get().(*[]attribute.KeyValue) + defer t.attributeSlicePool.Put(attrsP) + + // reslice to empty + opts := (*optsP)[:0] + attrs := (*attrsP)[:0] + + attrs = append(attrs, t.tracerAttrs...) if t.logConnectionDetails && conn != nil { - opts = append(opts, connectionAttributesFromConfig(conn.Config())) + attrs = append(attrs, connectionAttributesFromConfig(conn.Config())...) } if t.logSQLStatement { - opts = append(opts, trace.WithAttributes( + attrs = append(attrs, semconv.DBQueryText(data.SQL), - semconv.DBOperationName(t.sqlOperationName(data.SQL)), - )) + semconv.DBOperationName(t.spanNameFunc(data.SQL)), + ) if t.includeParams { - opts = append(opts, trace.WithAttributes(makeParamsAttribute(data.Args))) + attrs = append(attrs, makeParamsAttribute(data.Args)) } } + opts = append(opts, + trace.WithSpanKind(trace.SpanKindClient), + trace.WithAttributes(attrs...), + ) + spanName := data.SQL if t.trimQuerySpanName { - spanName = t.sqlOperationName(data.SQL) + spanName = t.spanNameFunc(data.SQL) } if t.prefixQuerySpanName { @@ -262,23 +311,33 @@ func (t *Tracer) TraceQueryEnd(ctx context.Context, _ *pgx.Conn, data pgx.TraceQ // returned context is used for the rest of the call and will be passed to // TraceCopyFromEnd. func (t *Tracer) TraceCopyFromStart(ctx context.Context, conn *pgx.Conn, data pgx.TraceCopyFromStartData) context.Context { - ctx = context.WithValue(ctx, startTimeCtxKey, time.Now()) + ctx = context.WithValue(ctx, startTimeCtxKey{}, time.Now()) if !trace.SpanFromContext(ctx).IsRecording() { return ctx } - opts := make([]trace.SpanStartOption, 0, 4) - opts = append(opts, - trace.WithSpanKind(trace.SpanKindClient), - trace.WithAttributes(t.tracerAttrs...), - trace.WithAttributes(semconv.DBCollectionName(data.TableName.Sanitize())), - ) + optsP := t.spanStartOptionsPool.Get().(*[]trace.SpanStartOption) + defer t.spanStartOptionsPool.Put(optsP) + attrsP := t.attributeSlicePool.Get().(*[]attribute.KeyValue) + defer t.attributeSlicePool.Put(attrsP) + + // reslice to empty + opts := (*optsP)[:0] + attrs := (*attrsP)[:0] + + attrs = append(attrs, t.tracerAttrs...) + attrs = append(attrs, semconv.DBCollectionName(data.TableName.Sanitize())) if t.logConnectionDetails && conn != nil { - opts = append(opts, connectionAttributesFromConfig(conn.Config())) + attrs = append(attrs, connectionAttributesFromConfig(conn.Config())...) } + opts = append(opts, + trace.WithSpanKind(trace.SpanKindClient), + trace.WithAttributes(attrs...), + ) + ctx, _ = t.tracer.Start(ctx, "copy_from "+data.TableName.Sanitize(), opts...) return ctx @@ -303,7 +362,7 @@ func (t *Tracer) TraceCopyFromEnd(ctx context.Context, _ *pgx.Conn, data pgx.Tra // context is used for the rest of the call and will be passed to // TraceBatchQuery and TraceBatchEnd. func (t *Tracer) TraceBatchStart(ctx context.Context, conn *pgx.Conn, data pgx.TraceBatchStartData) context.Context { - ctx = context.WithValue(ctx, startTimeCtxKey, time.Now()) + ctx = context.WithValue(ctx, startTimeCtxKey{}, time.Now()) if !trace.SpanFromContext(ctx).IsRecording() { return ctx @@ -314,17 +373,27 @@ func (t *Tracer) TraceBatchStart(ctx context.Context, conn *pgx.Conn, data pgx.T size = b.Len() } - opts := make([]trace.SpanStartOption, 0, 4) - opts = append(opts, - trace.WithSpanKind(trace.SpanKindClient), - trace.WithAttributes(t.tracerAttrs...), - trace.WithAttributes(semconv.DBOperationBatchSize(size)), - ) + optsP := t.spanStartOptionsPool.Get().(*[]trace.SpanStartOption) + defer t.spanStartOptionsPool.Put(optsP) + attrsP := t.attributeSlicePool.Get().(*[]attribute.KeyValue) + defer t.attributeSlicePool.Put(attrsP) + + // reslice to empty + opts := (*optsP)[:0] + attrs := (*attrsP)[:0] + + attrs = append(attrs, t.tracerAttrs...) + attrs = append(attrs, semconv.DBOperationBatchSize(size)) if t.logConnectionDetails && conn != nil { - opts = append(opts, connectionAttributesFromConfig(conn.Config())) + attrs = append(attrs, connectionAttributesFromConfig(conn.Config())...) } + opts = append(opts, + trace.WithSpanKind(trace.SpanKindClient), + trace.WithAttributes(attrs...), + ) + ctx, _ = t.tracer.Start(ctx, "batch start", opts...) return ctx @@ -338,30 +407,40 @@ func (t *Tracer) TraceBatchQuery(ctx context.Context, conn *pgx.Conn, data pgx.T return } - opts := make([]trace.SpanStartOption, 0, 6) - opts = append(opts, - trace.WithSpanKind(trace.SpanKindClient), - trace.WithAttributes(t.tracerAttrs...), - ) + optsP := t.spanStartOptionsPool.Get().(*[]trace.SpanStartOption) + defer t.spanStartOptionsPool.Put(optsP) + attrsP := t.attributeSlicePool.Get().(*[]attribute.KeyValue) + defer t.attributeSlicePool.Put(attrsP) + + // reslice to empty + opts := (*optsP)[:0] + attrs := (*attrsP)[:0] + + attrs = append(attrs, t.tracerAttrs...) if t.logConnectionDetails && conn != nil { - opts = append(opts, connectionAttributesFromConfig(conn.Config())) + attrs = append(attrs, connectionAttributesFromConfig(conn.Config())...) } if t.logSQLStatement { - opts = append(opts, trace.WithAttributes( + attrs = append(attrs, semconv.DBQueryText(data.SQL), - semconv.DBOperationName(t.sqlOperationName(data.SQL)), - )) + semconv.DBOperationName(t.spanNameFunc(data.SQL)), + ) if t.includeParams { - opts = append(opts, trace.WithAttributes(makeParamsAttribute(data.Args))) + attrs = append(attrs, makeParamsAttribute(data.Args)) } } + opts = append(opts, + trace.WithSpanKind(trace.SpanKindClient), + trace.WithAttributes(attrs...), + ) + var spanName string if t.trimQuerySpanName { - spanName = t.sqlOperationName(data.SQL) + spanName = t.spanNameFunc(data.SQL) if t.prefixQuerySpanName { spanName = "query " + spanName } @@ -393,22 +472,32 @@ func (t *Tracer) TraceBatchEnd(ctx context.Context, _ *pgx.Conn, data pgx.TraceB // calls. The returned context is used for the rest of the call and will be // passed to TraceConnectEnd. func (t *Tracer) TraceConnectStart(ctx context.Context, data pgx.TraceConnectStartData) context.Context { - ctx = context.WithValue(ctx, startTimeCtxKey, time.Now()) + ctx = context.WithValue(ctx, startTimeCtxKey{}, time.Now()) if !trace.SpanFromContext(ctx).IsRecording() { return ctx } - opts := make([]trace.SpanStartOption, 0, 3) - opts = append(opts, - trace.WithSpanKind(trace.SpanKindClient), - trace.WithAttributes(t.tracerAttrs...), - ) + optsP := t.spanStartOptionsPool.Get().(*[]trace.SpanStartOption) + defer t.spanStartOptionsPool.Put(optsP) + attrsP := t.attributeSlicePool.Get().(*[]attribute.KeyValue) + defer t.attributeSlicePool.Put(attrsP) + + // reslice to empty + opts := (*optsP)[:0] + attrs := (*attrsP)[:0] + + attrs = append(attrs, t.tracerAttrs...) if t.logConnectionDetails && data.ConnConfig != nil { - opts = append(opts, connectionAttributesFromConfig(data.ConnConfig)) + attrs = append(attrs, connectionAttributesFromConfig(data.ConnConfig)...) } + opts = append(opts, + trace.WithSpanKind(trace.SpanKindClient), + trace.WithAttributes(attrs...), + ) + ctx, _ = t.tracer.Start(ctx, "connect", opts...) return ctx @@ -429,35 +518,45 @@ func (t *Tracer) TraceConnectEnd(ctx context.Context, data pgx.TraceConnectEndDa // context is used for the rest of the call and will be passed to // TracePrepareEnd. func (t *Tracer) TracePrepareStart(ctx context.Context, conn *pgx.Conn, data pgx.TracePrepareStartData) context.Context { - ctx = context.WithValue(ctx, startTimeCtxKey, time.Now()) + ctx = context.WithValue(ctx, startTimeCtxKey{}, time.Now()) if !trace.SpanFromContext(ctx).IsRecording() { return ctx } - opts := make([]trace.SpanStartOption, 0, 6) - opts = append(opts, - trace.WithSpanKind(trace.SpanKindClient), - trace.WithAttributes(t.tracerAttrs...), - ) + optsP := t.spanStartOptionsPool.Get().(*[]trace.SpanStartOption) + defer t.spanStartOptionsPool.Put(optsP) + attrsP := t.attributeSlicePool.Get().(*[]attribute.KeyValue) + defer t.attributeSlicePool.Put(attrsP) + + // reslice to empty + opts := (*optsP)[:0] + attrs := (*attrsP)[:0] + + attrs = append(attrs, t.tracerAttrs...) if data.Name != "" { - trace.WithAttributes(PrepareStmtNameKey.String(data.Name)) + attrs = append(attrs, PrepareStmtNameKey.String(data.Name)) } if t.logConnectionDetails && conn != nil { - opts = append(opts, connectionAttributesFromConfig(conn.Config())) + attrs = append(attrs, connectionAttributesFromConfig(conn.Config())...) } - opts = append(opts, trace.WithAttributes(semconv.DBOperationName(t.sqlOperationName(data.SQL)))) + attrs = append(attrs, semconv.DBOperationName(t.spanNameFunc(data.SQL))) if t.logSQLStatement { - opts = append(opts, trace.WithAttributes(semconv.DBQueryText(data.SQL))) + attrs = append(attrs, semconv.DBQueryText(data.SQL)) } + opts = append(opts, + trace.WithSpanKind(trace.SpanKindClient), + trace.WithAttributes(attrs...), + ) + spanName := data.SQL if t.trimQuerySpanName { - spanName = t.sqlOperationName(data.SQL) + spanName = t.spanNameFunc(data.SQL) } if t.prefixQuerySpanName { spanName = "prepare " + spanName @@ -482,22 +581,32 @@ func (t *Tracer) TracePrepareEnd(ctx context.Context, _ *pgx.Conn, data pgx.Trac // TraceAcquireStart is called at the beginning of Acquire. // The returned context is used for the rest of the call and will be passed to the TraceAcquireEnd. func (t *Tracer) TraceAcquireStart(ctx context.Context, pool *pgxpool.Pool, data pgxpool.TraceAcquireStartData) context.Context { - ctx = context.WithValue(ctx, startTimeCtxKey, time.Now()) + ctx = context.WithValue(ctx, startTimeCtxKey{}, time.Now()) if !trace.SpanFromContext(ctx).IsRecording() { return ctx } - opts := make([]trace.SpanStartOption, 0, 3) - opts = append(opts, - trace.WithSpanKind(trace.SpanKindClient), - trace.WithAttributes(t.tracerAttrs...), - ) + optsP := t.spanStartOptionsPool.Get().(*[]trace.SpanStartOption) + defer t.spanStartOptionsPool.Put(optsP) + attrsP := t.attributeSlicePool.Get().(*[]attribute.KeyValue) + defer t.attributeSlicePool.Put(attrsP) + + // reslice to empty + opts := (*optsP)[:0] + attrs := (*attrsP)[:0] + + attrs = append(attrs, t.tracerAttrs...) if t.logConnectionDetails && pool != nil && pool.Config() != nil && pool.Config().ConnConfig != nil { - opts = append(opts, connectionAttributesFromConfig(pool.Config().ConnConfig)) + attrs = append(attrs, connectionAttributesFromConfig(pool.Config().ConnConfig)...) } + opts = append(opts, + trace.WithSpanKind(trace.SpanKindClient), + trace.WithAttributes(attrs...), + ) + ctx, _ = t.tracer.Start(ctx, "pool.acquire", opts...) return ctx diff --git a/tracer_benchmark_test.go b/tracer_benchmark_test.go index 1c2595c..48fad83 100644 --- a/tracer_benchmark_test.go +++ b/tracer_benchmark_test.go @@ -1,3 +1,6 @@ +//go:build go1.24 +// +build go1.24 + package otelpgx_test import ( @@ -41,8 +44,7 @@ func BenchmarkTracer(b *testing.B) { var maxConns int32 b.ReportAllocs() - b.ResetTimer() - for range b.N { + for b.Loop() { tx, err := pool.Begin(ctx) if err != nil { b.Fatal(err) diff --git a/tracer_test.go b/tracer_test.go index 8ce6a0d..e1ac63d 100644 --- a/tracer_test.go +++ b/tracer_test.go @@ -51,53 +51,53 @@ func TestTracer_sqlOperationName(t *testing.T) { { name: "Functional span name (-- comment style)", query: "-- name: GetUsers :many\nSELECT * FROM users", - tracer: NewTracer(WithSpanNameFunc(defaultSpanNameFunc)), + tracer: NewTracer(WithSpanNameFunc(testSpanNameFunc)), expName: "GetUsers :many", }, { name: "Functional span name (/**/ comment style)", query: "/* name: GetBooks :many */\nSELECT * FROM books", - tracer: NewTracer(WithSpanNameFunc(defaultSpanNameFunc)), + tracer: NewTracer(WithSpanNameFunc(testSpanNameFunc)), expName: "GetBooks :many", }, { name: "Functional span name (# comment style)", query: "# name: GetRecords :many\nSELECT * FROM records", - tracer: NewTracer(WithSpanNameFunc(defaultSpanNameFunc)), + tracer: NewTracer(WithSpanNameFunc(testSpanNameFunc)), expName: "GetRecords :many", }, { name: "Functional span name (no annotation)", query: "--\nSELECT * FROM user", - tracer: NewTracer(WithSpanNameFunc(defaultSpanNameFunc)), + tracer: NewTracer(WithSpanNameFunc(testSpanNameFunc)), expName: sqlOperationUnknown, }, { name: "Custom SQL name query (normal comment)", query: "-- foo \nSELECT * FROM users", - tracer: NewTracer(WithSpanNameFunc(defaultSpanNameFunc)), + tracer: NewTracer(WithSpanNameFunc(testSpanNameFunc)), expName: sqlOperationUnknown, }, { name: "Custom SQL name query (invalid formatting)", query: "foo \nSELECT * FROM users", - tracer: NewTracer(WithSpanNameFunc(defaultSpanNameFunc)), + tracer: NewTracer(WithSpanNameFunc(testSpanNameFunc)), expName: sqlOperationUnknown, }, } for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { tr := tt.tracer - if got := tr.sqlOperationName(tt.query); got != tt.expName { + if got := tr.spanNameFunc(tt.query); got != tt.expName { t.Errorf("Tracer.sqlOperationName() = %v, want %v", got, tt.expName) } }) } } -// defaultSpanNameFunc is an utility function for testing that attempts to get +// testSpanNameFunc is an utility function for testing that attempts to get // the first name of the query from a given SQL statement. -var defaultSpanNameFunc SpanNameFunc = func(query string) string { +var testSpanNameFunc SpanNameFunc = func(query string) string { for _, line := range strings.Split(query, "\n") { var prefix string switch {