Request Tracing

how-to

Collecting information about an individual request and its response is an essential feature of every observability stack.

To give insight into a request/response flow, the SDK provides a RequestTracer interface and ships with both a default implementation as well as modules that can be plugged into feed the traces to external systems (including OpenTelemetry).

The Default ThresholdLoggingTracer

By default, the SDK will emit information about requests that are over a configurable threshold every 10 seconds. Note that if no requests are over the threshold no event / log will be emitted.

It is possible to customize this behavior by modifying the configuration:

ThresholdLoggingTracerConfig.Builder config = ThresholdLoggingTracerConfig.builder()
    .emitInterval(Duration.ofMinutes(1)).kvThreshold(Duration.ofSeconds(2));

CoreEnvironment environment = CoreEnvironment.builder().thresholdLoggingTracerConfig(config).build();

In this case the emit interval is one minute and Key/Value requests will only be considered if their latency is greater or equal than two seconds.

The JSON blob emitted looks similar to the following (prettified here for readability):

[
   {
      "top":[
         {
            "operation_name":"GetRequest",
            "server_us":2,
            "last_local_id":"E64FED2600000001/00000000EA6B514E",
            "last_local_address":"127.0.0.1:51807",
            "last_remote_address":"127.0.0.1:11210",
            "last_dispatch_us":2748,
            "last_operation_id":"0x9",
            "total_us":324653
         },
         {
            "operation_name":"GetRequest",
            "server_us":0,
            "last_local_id":"E64FED2600000001/00000000EA6B514E",
            "last_local_address":"127.0.0.1:51807",
            "last_remote_address":"127.0.0.1:11210",
            "last_dispatch_us":1916,
            "last_operation_id":"0x1b692",
            "total_us":2007
         }
      ],
      "service":"kv",
      "count":2
   }
]

For each service (e.g. Key/Value or Query) an entry exists in the outer JSON array. The top N (10 by default) slowest operations are collected and displayed, sorted by the total duration. This promotes quick visibility of the "worst offenders" and more efficient troubleshooting.

Please note that in future releases this format is planned to change for easier readability, so we do not provide any stability guarantees on the logging output format and it might change between minor versions.

A new, yet to be stabilized, format can be enabled by setting the com.couchbase.thresholdRequestTracerNewOutputFormat system property to true. More information will be provided as we get closer to stabilization.

OpenTelemetry Integration

The built-in tracer is great if you do not have a centralized monitoring system, but if you already plug into the OpenTelemetry ecosystem we want to make sure to provide first-class support.

The first thing you need to do is include an andditional dependency which provides the interoperability code:

<dependency>
    <groupId>com.couchbase.client</groupId>
    <artifactId>tracing-opentelemetry</artifactId>
    <version>1.1.4</version>
</dependency>

You also need to include your downstream exporter of choice, in the following example we’ll use Jaeger tracing:

<dependency>
    <groupId>io.opentelemetry</groupId>
    <artifactId>opentelemetry-exporter-jaeger</artifactId>
    <version>0.11.0</version>
</dependency>
<dependency>
    <groupId>io.grpc</groupId>
    <artifactId>grpc-protobuf</artifactId>
    <version>1.28.0</version>
</dependency>
<dependency>
    <groupId>io.grpc</groupId>
    <artifactId>grpc-netty-shaded</artifactId>
    <version>1.28.0</version>
</dependency>

Next up, initialize the jaeger tracer:

// Create a channel towards Jaeger end point
ManagedChannel jaegerChannel = ManagedChannelBuilder.forAddress("localhost", 14250).usePlaintext().build();

// Export traces to Jaeger
JaegerGrpcSpanExporter jaegerExporter = JaegerGrpcSpanExporter.builder().setServiceName("otel-jaeger-example")
    .setChannel(jaegerChannel).setDeadlineMs(30000).build();

// Set to process the spans by the Jaeger Exporter
OpenTelemetrySdk.getGlobalTracerManagement()
    .addSpanProcessor(SimpleSpanProcessor.builder(jaegerExporter).build());

Once the exporter is set up, it can be wrapped into the OpenTelemetryRequestTracer and passed into the environment.

// Wrap Tracer
RequestTracer tracer = OpenTelemetryRequestTracer.wrap(OpenTelemetry.get());

ClusterEnvironment environment = ClusterEnvironment.builder().requestTracer(tracer).build();

At this point, all traces will be sent into the OpenTelemetry exporter. If you want to set a parent for a SDK request, you can do it in the respective *Options:

GetResult result = collection.get(
    "my-doc",
    getOptions().parentSpan(OpenTelemetryRequestSpan.wrap(parentSpan))
)

OpenTracing Integration

In addition to OpenTelemetry, we also provide support for OpenTracing for legacy systems which have not yet migrated to OpenTelemetry. Note that we still recommend to migrate eventually since OpenTracing has been sunsetted.

You need to include the tracing-opentracing module:

<dependency>
    <groupId>com.couchbase.client</groupId>
    <artifactId>tracing-opentracing</artifactId>
    <version>0.3.3</version>
</dependency>

And then wrap the Tracer:

ClusterEnvironment environment = ClusterEnvironment
    .builder()
    .requestTracer(OpenTracingRequestTracer.wrap(tracer))
    .build();