Memory leak issue with Open Telemetry and jaeger exporter

[varun06]

We are using Open Telemetry in a reverse Proxy at scale and seeing memory leak.

func InitTracing(serviceName string, collectorEndpoint string, sample float64) (func(), error) {
	tc := propagation.TraceContext{}
	// Register the TraceContext propagator globally.
	otel.SetTextMapPropagator(tc)

	// Create and install Jaeger export pipeline.
	return jaeger.InstallNewPipeline(
		jaeger.WithCollectorEndpoint(collectorEndpoint),
		jaeger.WithProcess(jaeger.Process{
			ServiceName: serviceName,
			Tags: []label.KeyValue{
				label.String("exporter", "jaeger"),
			},
		}),
		jaeger.WithSDK(&sdktrace.Config{DefaultSampler: sdktrace.TraceIDRatioBased(sample)}),
	)
}

This is how I am initiating tracer.

	if cfg.TracingEnabled {
		// Initialize tracing and set global tracer
		flush, err := tracing.InitTracing("odnd", cfg.TracingCollectorEndpoint, cfg.TracingSampleValue)
		if err != nil {
			proxyLogger.Error("Failed to initialize tracing collector", logger.Error(err))
		}
		if flush != nil {
			defer flush()
		}
	}

This is how it is used to create a global tracer.

	tc := otel.GetTextMapPropagator()
	ctx := tc.Extract(originalReq.Context(), originalReq.Header)

	tracer := otel.Tracer(tracing.TracerName)

	tracingCtx, span := tracer.Start(ctx, "serveHTTP", trace.WithSpanKind(trace.SpanKindServer))
	originalReq = originalReq.WithContext(tracingCtx)
	defer span.End()

That's how we are creating a span and then few more child spans are created. But we are seeing this

It goes up as we add more spans and off course that impacts GC and CPU usage on node. Can someone please have a look and let me know if i am doing something wrong in code or it's related to lib??

[MrAlias]

Thanks for the bug report. Have you been able to see the error while running with a profiler?

Also, when you defer the end of the span, does that function ever return?

[varun06]

Hey @MrAlias

It seems that problem was calling GetTracer every time we were creating a new Span(Bug). But I was wondering, shouldn't GetTracer be a Singleton??

[MrAlias]

Hey @MrAlias

It seems that problem was calling GetTracer every time we were creating a new Span(Bug). But I was wondering, shouldn't GetTracer be a Singleton??

Thanks for looking into this. The Tracer returned from GetTracer should indeed be a reference to the same Tracer value if it is named the same. Do you have evidence this is not happening? That definitely sounds like a bug if so.

[varun06]

I have lost the pprof that shows something like that, but i can share problematic code that was creating this problem.

func AddSpanToRequest(req *http.Request, spanName string) (*http.Request, trace.Span) {
 	var (
 		span               trace.Span
 		reqCtx, tracingCtx context.Context
 		ok                 bool
 	)

 	if req == nil {
 		return nil, nil
 	}

 	reqCtx = req.Context()
 	val := reqCtx.Value(ContextKey)
 	if tracingCtx, ok = val.(context.Context); !ok {
 		tracingCtx = context.Background()
 	}

 	tracer := global.Tracer(TracerName)
 	tracingCtx, span = tracer.Start(tracingCtx, spanName)
 	req = req.WithContext(context.WithValue(reqCtx, ContextKey, tracingCtx))
 	return req, span
}

and it was getting called every time someone created a new span. When i profiled, i remember seeing multiple tracer.

[brancz]

We are experiencing the exact same problem. We continuously profile our entire infrastructure, so we have profiling data available for everything. Let us know what would be useful to you! :)

Process start: https://share.polarsignals.com/7aef522/
Right before OOM: https://share.polarsignals.com/5bf8ce4/
Diff of the two profiles: https://share.polarsignals.com/8945fcd/

This data also highly suggests something within the global tracer to be leaking, but it's very possible that we're doing something wrong. Let me know what I can try or provide further that would be helpful!

[varun06]

@brancz Thanks for chiming in. I see nothing with those links . But yeah, we had same behavior. If I get some time this week, will try to read some code and see if I can find out, I am also planning to replicate this situation in a test env and see what is causing this.

[danp]

It's entirely possible I'm missing context, and apologies in advance if so! But looking at the profiles @brancz shared it gets me wondering when things added to p.tracers here would be removed:

opentelemetry-go/internal/global/trace.go

Lines 90 to 91 in e499ca8

	t := &tracer{name: name, opts: opts}
	p.tracers = append(p.tracers, t)

If, for example, the grpc UnaryClientInterceptor is calling Tracer like so for every request:

https://github.com/open-telemetry/opentelemetry-go-contrib/blob/1c687598a61840d67e56c9c7707af4997e1a057b/instrumentation/google.golang.org/grpc/otelgrpc/interceptor.go#L81-L84

When would its associated tracer in p.tracers be removed?

[michelaquino]

Hi @bogdandrutu
do you have a forecast to release this fix?

[MrAlias]

@michelaquino we are hoping to make a release by the end of the week that will contain this fix. Please reach out to us in the CNCF otel-go slack channel if you have any more questions about the release.