diff --git a/README.md b/README.md index 0e8ec15..8960beb 100644 --- a/README.md +++ b/README.md @@ -1,4 +1,4 @@ -[![Go Reference](https://pkg.go.dev/badge/github.com/exaring/otelpgx.svg)](https://pkg.go.dev/github.com/exaring/otelpgx) +[![Go Reference](https://pkg.go.dev/badge/github.com/overmindtech/otelpgx.svg)](https://pkg.go.dev/github.com/overmindtech/otelpgx) # otelpgx @@ -21,7 +21,7 @@ go get github.com/jackc/pgx/v5 Install the library: ```go -go get github.com/exaring/otelpgx +go get github.com/overmindtech/otelpgx ``` Create the tracer as part of your connection: diff --git a/go.mod b/go.mod index 42c792a..ec173b1 100644 --- a/go.mod +++ b/go.mod @@ -1,4 +1,4 @@ -module github.com/exaring/otelpgx +module github.com/overmindtech/otelpgx go 1.22.0 diff --git a/tracer.go b/tracer.go index ce1a130..3fc44c3 100644 --- a/tracer.go +++ b/tracer.go @@ -21,8 +21,8 @@ import ( ) const ( - tracerName = "github.com/exaring/otelpgx" - meterName = "github.com/exaring/otelpgx" + tracerName = "github.com/overmindtech/otelpgx" + meterName = "github.com/overmindtech/otelpgx" ) const ( @@ -52,6 +52,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{} @@ -530,116 +533,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. -func (t *Tracer) TraceAcquireStart(ctx context.Context, pool *pgxpool.Pool, data pgxpool.TraceAcquireStartData) 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 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. func (t *Tracer) TraceAcquireEnd(ctx context.Context, _ *pgxpool.Pool, data pgxpool.TraceAcquireEndData) { - 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_benchmark_test.go b/tracer_benchmark_test.go index 48fad83..adaac6d 100644 --- a/tracer_benchmark_test.go +++ b/tracer_benchmark_test.go @@ -8,7 +8,7 @@ import ( "os" "testing" - "github.com/exaring/otelpgx" + "github.com/overmindtech/otelpgx" "github.com/jackc/pgx/v5/pgxpool" sdktrace "go.opentelemetry.io/otel/sdk/trace" "go.opentelemetry.io/otel/sdk/trace/tracetest" diff --git a/tracer_span_test.go b/tracer_span_test.go new file mode 100644 index 0000000..017e73a --- /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") + } +}