Debug Logging for sdk/trace (#2500)

* Debug Logging for sdk/trace

* Fixes spelling, adds marshaling to attribute sets

Co-authored-by: Aaron Clawson <MadVikingGod@users.noreply.github.com>
Co-authored-by: Anthony Mirabella <a9@aneurysm9.com>

CHANGELOG.md

@@ -11,6 +11,7 @@ This project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.htm
 ### Added
 
 - Support `OTEL_EXPORTER_ZIPKIN_ENDPOINT` env to specify zipkin collector endpoint (#2490)
+- Log the configuration of TracerProviders, and Tracers for debugging. To enable use a logger with Verbosity (V level) >=1
 
 ### Changed
 

attribute/set.go

@@ -410,6 +410,15 @@ func (l *Set) MarshalJSON() ([]byte, error) {
 	return json.Marshal(l.equivalent.iface)
 }
 
+// MarshalLog is the marshaling function used by the logging system to represent this exporter.
+func (l Set) MarshalLog() interface{} {
+	kvs := make(map[string]string)
+	for _, kv := range l.ToSlice() {
+		kvs[string(kv.Key)] = kv.Value.Emit()
+	}
+	return kvs
+}
+
 // Len implements `sort.Interface`.
 func (l *Sortable) Len() int {
 	return len(*l)

example/namedtracer/main.go

@@ -55,7 +55,7 @@ func initTracer() {
 
 func main() {
 	// Set logging level to info to see SDK status messages
-	stdr.SetVerbosity(1)
+	stdr.SetVerbosity(5)
 
 	// initialize trace provider.
 	initTracer()

exporters/stdout/stdouttrace/trace.go

@@ -106,3 +106,14 @@ func (e *Exporter) Shutdown(ctx context.Context) error {
 	}
 	return nil
 }
+
+// MarshalLog is the marshaling function used by the logging system to represent this exporter.
+func (e *Exporter) MarshalLog() interface{} {
+	return struct {
+		Type           string
+		WithTimestamps bool
+	}{
+		Type:           "stdout",
+		WithTimestamps: e.timestamps,
+	}
+}

sdk/go.mod

@@ -5,6 +5,7 @@ go 1.16
 replace go.opentelemetry.io/otel => ../
 
 require (
+	github.com/go-logr/logr v1.2.2
 	github.com/google/go-cmp v0.5.6
 	github.com/stretchr/testify v1.7.0
 	go.opentelemetry.io/otel v1.3.0

sdk/resource/resource.go

@@ -109,6 +109,17 @@ func (r *Resource) String() string {
 	return r.attrs.Encoded(attribute.DefaultEncoder())
 }
 
+// MarshalLog is the marshaling function used by the logging system to represent this exporter.
+func (r *Resource) MarshalLog() interface{} {
+	return struct {
+		Attributes attribute.Set
+		SchemaURL  string
+	}{
+		Attributes: r.attrs,
+		SchemaURL:  r.schemaURL,
+	}
+}
+
 // Attributes returns a copy of attributes from the resource in a sorted order.
 // To avoid allocating a new slice, use an iterator.
 func (r *Resource) Attributes() []attribute.KeyValue {

sdk/trace/batch_span_processor.go

@@ -238,7 +238,7 @@ func (bsp *batchSpanProcessor) exportSpans(ctx context.Context) error {
 	}
 
 	if l := len(bsp.batch); l > 0 {
-		global.Debug("exporting spans", "count", len(bsp.batch))
+		global.Debug("exporting spans", "count", len(bsp.batch), "dropped", bsp.dropped)
 		err := bsp.e.ExportSpans(ctx, bsp.batch)
 
 		// A new batch is always created after exporting, even if the batch failed to be exported.
@@ -369,3 +369,16 @@ func (bsp *batchSpanProcessor) enqueueBlockOnQueueFull(ctx context.Context, sd R
 	}
 	return false
 }
+
+// MarshalLog is the marshaling function used by the logging system to represent this exporter.
+func (bsp *batchSpanProcessor) MarshalLog() interface{} {
+	return struct {
+		Type         string
+		SpanExporter SpanExporter
+		Config       BatchSpanProcessorOptions
+	}{
+		Type:         "BatchSpanProcessor",
+		SpanExporter: bsp.e,
+		Config:       bsp.o,
+	}
+}

sdk/trace/batch_span_processor_test.go

@@ -23,9 +23,11 @@ import (
 	"testing"
 	"time"
 
+	"github.com/go-logr/logr/funcr"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 
+	"go.opentelemetry.io/otel/internal/global"
 	sdktrace "go.opentelemetry.io/otel/sdk/trace"
 	"go.opentelemetry.io/otel/sdk/trace/tracetest"
 	"go.opentelemetry.io/otel/trace"
@@ -480,3 +482,44 @@ func TestBatchSpanProcessorForceFlushQueuedSpans(t *testing.T) {
 		assert.Len(t, exp.GetSpans(), i+1)
 	}
 }
+
+func BenchmarkSpanProcessor(b *testing.B) {
+	tp := sdktrace.NewTracerProvider(
+		sdktrace.WithBatcher(
+			tracetest.NewNoopExporter(),
+			sdktrace.WithMaxExportBatchSize(10),
+		))
+	tracer := tp.Tracer("bench")
+	ctx := context.Background()
+
+	b.ResetTimer()
+	b.ReportAllocs()
+
+	for i := 0; i < b.N; i++ {
+		for j := 0; j < 10; j++ {
+			_, span := tracer.Start(ctx, "bench")
+			span.End()
+		}
+	}
+}
+
+func BenchmarkSpanProcessorVerboseLogging(b *testing.B) {
+	global.SetLogger(funcr.New(func(prefix, args string) {}, funcr.Options{Verbosity: 5}))
+	tp := sdktrace.NewTracerProvider(
+		sdktrace.WithBatcher(
+			tracetest.NewNoopExporter(),
+			sdktrace.WithMaxExportBatchSize(10),
+		))
+	tracer := tp.Tracer("bench")
+	ctx := context.Background()
+
+	b.ResetTimer()
+	b.ReportAllocs()
+
+	for i := 0; i < b.N; i++ {
+		for j := 0; j < 10; j++ {
+			_, span := tracer.Start(ctx, "bench")
+			span.End()
+		}
+	}
+}

sdk/trace/provider.go

@@ -21,6 +21,7 @@ import (
 	"sync/atomic"
 
 	"go.opentelemetry.io/otel"
+	"go.opentelemetry.io/otel/internal/global"
 	"go.opentelemetry.io/otel/sdk/instrumentation"
 	"go.opentelemetry.io/otel/sdk/resource"
 	"go.opentelemetry.io/otel/trace"
@@ -52,6 +53,23 @@ type tracerProviderConfig struct {
 	resource *resource.Resource
 }
 
+// MarshalLog is the marshaling function used by the logging system to represent this exporter.
+func (cfg tracerProviderConfig) MarshalLog() interface{} {
+	return struct {
+		SpanProcessors  []SpanProcessor
+		SamplerType     string
+		IDGeneratorType string
+		SpanLimits      SpanLimits
+		Resource        *resource.Resource
+	}{
+		SpanProcessors:  cfg.processors,
+		SamplerType:     fmt.Sprintf("%T", cfg.sampler),
+		IDGeneratorType: fmt.Sprintf("%T", cfg.idGenerator),
+		SpanLimits:      cfg.spanLimits,
+		Resource:        cfg.resource,
+	}
+}
+
 type TracerProvider struct {
 	mu             sync.Mutex
 	namedTracer    map[instrumentation.Library]*tracer
@@ -91,6 +109,8 @@ func NewTracerProvider(opts ...TracerProviderOption) *TracerProvider {
 		resource:    o.resource,
 	}
 
+	global.Info("TracerProvider created", "config", o)
+
 	for _, sp := range o.processors {
 		tp.RegisterSpanProcessor(sp)
 	}
@@ -125,6 +145,7 @@ func (p *TracerProvider) Tracer(name string, opts ...trace.TracerOption) trace.T
 			instrumentationLibrary: il,
 		}
 		p.namedTracer[il] = t
+		global.Info("Tracer created", "name", name, "version", c.InstrumentationVersion(), "schemaURL", c.SchemaURL())
 	}
 	return t
 }

sdk/trace/simple_span_processor.go

@@ -115,3 +115,14 @@ func (ssp *simpleSpanProcessor) Shutdown(ctx context.Context) error {
 func (ssp *simpleSpanProcessor) ForceFlush(context.Context) error {
 	return nil
 }
+
+// MarshalLog is the marshaling function used by the logging system to represent this exporter.
+func (ssp *simpleSpanProcessor) MarshalLog() interface{} {
+	return struct {
+		Type     string
+		Exporter SpanExporter
+	}{
+		Type:     "SimpleSpanProcessor",
+		Exporter: ssp.exporter,
+	}
+}