diff --git a/options.go b/options.go index f987d4d..253366d 100644 --- a/options.go +++ b/options.go @@ -71,14 +71,6 @@ func WithTrimSQLInSpanName() Option { }) } -// WithDisableAcquireTracer disables tracing for connection acquire events from -// the connection pool. By default, acquire tracing is enabled. -func WithDisableAcquireTracer() Option { - return optionFunc(func(cfg *tracerConfig) { - cfg.disableAcquireTracer = true - }) -} - // SpanNameFunc is a function that can be used to generate a span name for a // SQL. The function will be called with the SQL statement as a parameter. type SpanNameFunc func(stmt string) string diff --git a/tracer.go b/tracer.go index e3ab16f..c9705c4 100644 --- a/tracer.go +++ b/tracer.go @@ -53,6 +53,9 @@ const ( PGXOperationTypeKey = attribute.Key("pgx.operation.type") // DBClientOperationErrorsKey represents the count of operation errors DBClientOperationErrorsKey = attribute.Key("db.client.operation.errors") + // PrepareDurationKey records the wall-clock time of a prepared-statement + // round-trip, in milliseconds, as an attribute on the parent query span. + PrepareDurationKey = attribute.Key("pgx.prepare.duration") ) type startTimeCtxKey struct{} @@ -81,7 +84,6 @@ type Tracer struct { logSQLStatement bool logConnectionDetails bool includeParams bool - disableAcquireTracer bool } type tracerConfig struct { @@ -97,7 +99,6 @@ type tracerConfig struct { logSQLStatement bool logConnectionDetails bool includeParams bool - disableAcquireTracer bool } // NewTracer returns a new Tracer. @@ -117,7 +118,6 @@ func NewTracer(opts ...Option) *Tracer { logSQLStatement: true, logConnectionDetails: true, includeParams: false, - disableAcquireTracer: false, } for _, opt := range opts { @@ -146,7 +146,6 @@ func NewTracer(opts ...Option) *Tracer { prefixQuerySpanName: cfg.prefixQuerySpanName, logSQLStatement: cfg.logSQLStatement, includeParams: cfg.includeParams, - disableAcquireTracer: cfg.disableAcquireTracer, } tracer.createMetrics() @@ -529,126 +528,41 @@ func (t *Tracer) TraceConnectEnd(ctx context.Context, data pgx.TraceConnectEndDa // TracePrepareStart is called at the beginning of Prepare calls. The returned // 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()) - - if !trace.SpanFromContext(ctx).IsRecording() { - return ctx - } - - 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 != "" { - attrs = append(attrs, PrepareStmtNameKey.String(data.Name)) - } - - if t.logConnectionDetails && conn != nil { - attrs = append(attrs, connectionAttributesFromConfig(conn.Config())...) - } - - attrs = append(attrs, semconv.DBOperationName(t.spanNameCtxFunc(ctx, data.SQL))) - - if t.logSQLStatement { - 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.spanNameCtxFunc(ctx, data.SQL) - } - if t.prefixQuerySpanName { - spanName = "prepare " + spanName - } - - ctx, _ = t.tracer.Start(ctx, spanName, opts...) - - return ctx +// +// No span is created for prepare. Instead, the prepare duration is recorded as +// the pgx.prepare.duration attribute (milliseconds) on the parent query span. +func (t *Tracer) TracePrepareStart(ctx context.Context, _ *pgx.Conn, _ pgx.TracePrepareStartData) context.Context { + return context.WithValue(ctx, startTimeCtxKey{}, time.Now()) } // TracePrepareEnd is called at the end of Prepare calls. func (t *Tracer) TracePrepareEnd(ctx context.Context, _ *pgx.Conn, data pgx.TracePrepareEndData) { - span := trace.SpanFromContext(ctx) t.incrementOperationErrorCount(ctx, data.Err, pgxOperationPrepare) t.recordOperationDuration(ctx, pgxOperationPrepare) - if !span.IsRecording() { - return + if startTime, ok := ctx.Value(startTimeCtxKey{}).(time.Time); ok { + span := trace.SpanFromContext(ctx) + if span.IsRecording() { + span.SetAttributes(PrepareDurationKey.Int64(time.Since(startTime).Milliseconds())) + } } - - recordSpanError(span, data.Err) - span.End() } // 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. -// If WithDisableAcquireTracer was set, then the function is no-op. -func (t *Tracer) TraceAcquireStart(ctx context.Context, pool *pgxpool.Pool, data pgxpool.TraceAcquireStartData) context.Context { - if t.disableAcquireTracer { - return ctx - } - - ctx = context.WithValue(ctx, startTimeCtxKey{}, time.Now()) - - if !trace.SpanFromContext(ctx).IsRecording() { - return ctx - } - - 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 { - 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 +// +// No span is created for pool.acquire. Pool acquire duration is tracked via the +// db.client.operation.duration metric (pgx.operation.type=acquire) and the pgxpool.* +// metrics from RecordStats. As a span it adds noise without actionable signal; pool +// contention is an environmental concern better diagnosed from aggregate metrics. +func (t *Tracer) TraceAcquireStart(ctx context.Context, _ *pgxpool.Pool, _ pgxpool.TraceAcquireStartData) context.Context { + return context.WithValue(ctx, startTimeCtxKey{}, time.Now()) } // TraceAcquireEnd is called when a connection has been acquired. -// If WithDisableAcquireTracer was set, then the function is no-op. func (t *Tracer) TraceAcquireEnd(ctx context.Context, _ *pgxpool.Pool, data pgxpool.TraceAcquireEndData) { - if t.disableAcquireTracer { - return - } - - span := trace.SpanFromContext(ctx) t.incrementOperationErrorCount(ctx, data.Err, pgxOperationAcquire) t.recordOperationDuration(ctx, pgxOperationAcquire) - - if !span.IsRecording() { - return - } - - recordSpanError(span, data.Err) - span.End() } func makeParamsAttribute(args []any) attribute.KeyValue { diff --git a/tracer_span_test.go b/tracer_span_test.go new file mode 100644 index 0000000..2247065 --- /dev/null +++ b/tracer_span_test.go @@ -0,0 +1,96 @@ +package otelpgx + +import ( + "context" + "testing" + + "github.com/jackc/pgx/v5" + "github.com/jackc/pgx/v5/pgxpool" + sdktrace "go.opentelemetry.io/otel/sdk/trace" + "go.opentelemetry.io/otel/sdk/trace/tracetest" +) + +func setupTestTracer(t *testing.T) (*Tracer, *tracetest.InMemoryExporter, *sdktrace.TracerProvider) { + t.Helper() + + exporter := tracetest.NewInMemoryExporter() + tp := sdktrace.NewTracerProvider( + sdktrace.WithSyncer(exporter), + sdktrace.WithSampler(sdktrace.AlwaysSample()), + ) + + tracer := NewTracer(WithTracerProvider(tp)) + return tracer, exporter, tp +} + +func TestTraceAcquire_NoSpan(t *testing.T) { + tracer, exporter, tp := setupTestTracer(t) + + parentTracer := tp.Tracer("test") + ctx, parentSpan := parentTracer.Start(context.Background(), "parent") + + ctx = tracer.TraceAcquireStart(ctx, nil, pgxpool.TraceAcquireStartData{}) + tracer.TraceAcquireEnd(ctx, nil, pgxpool.TraceAcquireEndData{}) + + parentSpan.End() + + spans := exporter.GetSpans() + + for _, s := range spans { + if s.Name == "pool.acquire" { + t.Error("pool.acquire span should not be created") + } + } + + if len(spans) != 1 { + t.Errorf("expected exactly 1 span (the parent), got %d", len(spans)) + } + if spans[0].Name != "parent" { + t.Errorf("expected span name 'parent', got %q", spans[0].Name) + } +} + +func TestTracePrepare_NoSpan_SetsAttribute(t *testing.T) { + tracer, exporter, tp := setupTestTracer(t) + + parentTracer := tp.Tracer("test") + ctx, parentSpan := parentTracer.Start(context.Background(), "query SELECT 1") + + ctx = tracer.TracePrepareStart(ctx, nil, pgx.TracePrepareStartData{ + Name: "stmt1", + SQL: "SELECT 1", + }) + tracer.TracePrepareEnd(ctx, nil, pgx.TracePrepareEndData{}) + + parentSpan.End() + + spans := exporter.GetSpans() + + for _, s := range spans { + if s.Name == "prepare SELECT 1" || s.Name == "SELECT 1" { + t.Errorf("prepare span should not be created, found span %q", s.Name) + } + } + + if len(spans) != 1 { + t.Errorf("expected exactly 1 span (the parent), got %d", len(spans)) + } + + parentAttrs := spans[0].Attributes + var found bool + for _, attr := range parentAttrs { + if attr.Key == PrepareDurationKey { + found = true + if attr.Value.Type().String() != "INT64" { + t.Errorf("expected pgx.prepare.duration to be INT64, got %s", attr.Value.Type()) + } + if attr.Value.AsInt64() < 0 { + t.Errorf("expected pgx.prepare.duration >= 0, got %d", attr.Value.AsInt64()) + } + } + } + + if !found { + t.Error("expected pgx.prepare.duration attribute on parent span, but not found") + } +}