Latency with otelhttp and google cloudtrace

[bignastybryce]

Hi,
I'm not sure if this is the right place to ask this, or if the issue is in otelhttp, otel, or the google cloud trace library, but enabling tracing is introducing ~500ms latency on requests that normally take under 10ms. Setting the sampling ratio to 0 results in the requests being filled in the normal time. This is the same in OTel version 0.16.0 and 0.19.0. I'm happy to provide more details, if this is in fact the right place for this discussion. If not, I would greatly appreciate a point in the right direction.

EDIT: I should probably note that the services are running in GKE.

Thanks,
-Bryce.

[Aneurysm9]

Can you share some info about your setup? How is the exporter configured? Are you using a SimpleSpanProcessor or a BatchSpanProcessor? Is the latency visible in the trace spans? Is it possible that the export destination is in a different geographic region?

[bignastybryce]

Hi, thanks for the reply. Here is the function that all of the services use to set up the exporter:

package middleware

import (
	texporter "github.com/GoogleCloudPlatform/opentelemetry-operations-go/exporter/trace"
	"go.opentelemetry.io/otel"
	"go.opentelemetry.io/otel/exporters/stdout"
	"go.opentelemetry.io/otel/propagation"
	"go.opentelemetry.io/otel/sdk/export/trace"
	"go.opentelemetry.io/otel/sdk/resource"
	sdktrace "go.opentelemetry.io/otel/sdk/trace"
	"go.opentelemetry.io/otel/semconv"
)

func InitTracer(label, projectID string, samplingRatio float64) error {
	var exporter trace.SpanExporter
	var err error
	// Use the stackdriver exporter if the projectID is not empty
	// otherwise, use stdout
	if projectID == "" {
		exporter, err = stdout.NewExporter(stdout.WithPrettyPrint())
		if err != nil {
			return err
		}
	} else {
		exporter, err = texporter.NewExporter(texporter.WithProjectID(projectID))
		if err != nil {
			return err
		}
	}

	// If there is a parent span, respect its sampling decision, otherwise decide by TraceIDRatio
	sampler := sdktrace.ParentBased(sdktrace.TraceIDRatioBased(samplingRatio))

	// In a production application, use sdktrace.TraceIDRatioBased with a desired ratio. >=1 means always, <=0 means never
	tp := sdktrace.NewTracerProvider(sdktrace.WithSampler(sampler),
		sdktrace.WithSyncer(exporter),
		sdktrace.WithResource(resource.NewWithAttributes(semconv.ServiceNameKey.String(label))))
	if err != nil {
		return err
	}
	otel.SetTracerProvider(tp)
	otel.SetTextMapPropagator(propagation.NewCompositeTextMapPropagator(propagation.TraceContext{}, propagation.Baggage{}))
	return nil
}

Here is how we set up the http handler:

	monitoringFilter := filters.None(filters.Path("/health"), filters.Path("/metrics"))
	otelHandler := otelhttp.NewHandler(server.router, fmt.Sprintf("%s instrumenting router", serviceName), otelhttp.WithFilter(monitoringFilter))

	listenPort := getEnv("APP_PORT", "9090")
	logr.Infof("Starting User App HTTP server listening on port %s", listenPort)
	logr.Fatal(http.ListenAndServe(fmt.Sprintf("%s:%s", os.Getenv("BINDHOST"), listenPort), otelHandler))

The latencies are visible in the traces in the google cloud console. The parent span of a remote call shows around 500ms or so, while the child span shows around 6ms.

These services are all in one region, though they are split in two GCP projects.

Thanks,
-Bryce.

[MrAlias]

It looks like you are using a simple span processor in your setup (i.e. WithSyncer). This will try to export each span the moment it is ended.

Can you try using a BatchSpanProcessor instead by setting up with WithBatcher and see if that helps?

[bignastybryce]

Hi. Thanks for the response. I changed to WithBatcher, but it didn't make a detectable difference.

[MrAlias]

Are you able to profile your code? Maybe with pprof? It's hard to help without knowing what the culprit is.

[bignastybryce]

@MrAlias - it looks like your first answer was the right one, after all. When I was looking at the profiler, I realized that the remote service (the child span) was still calling the simple span processor. After I updated that service as well, the extra latency went away.

Thanks for your help.
-Bryce.