Deepdive into the Couchbase SDK Timeouts and Request Tracing

If you are a developer, no matter which database solution you develop, you will come across Timeout Exceptions. As a Couchbase developer, this is no different. Technically, timeouts happen because the SDK tried to execute a request against the Couchbase Server within the specified time but couldn't complete it in time. The challenging part is understanding why this happens. 

Since SDKs operate within the app's runtime environment (which could be in a language on a VM or a container and using a shared network), any component in this environment can pause or become congested. Additionally, many of these components, including TCP, are designed to abstract away details, making it even more difficult to pinpoint the exact cause.

To facilitate identifying these timeouts, Couchbase Team started contributing to the OpenTracing project, by adding trace spans to our SDKs and eventually to the cluster. Typically, tracing spans are created while calling between microservices, but we collaborated with the OpenTracing and later the OpenTelemetry community to explore ways to trace within a software stack. 

We can’t fully pinpoint the exact cause of the timeout through the SDK, but we believe that representing tracing as a stack of spans and allowing users to view the data in an aggregate, can help users quickly identify where to look next by ruling out some potential causes.

According to the Couchbase Response Time Observability (RTO) v2 RFC (under review), we define a set of spans, each encompassing the next:

• The Outer Request Span (or simply Request Span)
• The Encoding Span
• The Dispatch to Server Span

Request Span

This span starts when the app makes a request to the SDK and ends when the SDK returns the data to the app. An important detail to note here is that any unmarshaling of the response should not be included in the request span, but the opposite is true. For instance, in Java, when the app logic calls the Key Value upsert() with a POJO, the conversion to JSON is part of the request span. However, the `contentAs()` call to convert responses back to the POJO would not be included. 

Encoding Span

This span represents the time that is spent for the conversion mentioned above within the Request span. Essentially, it measures how long it takes to convert the data passed to the API into the format the SDK is configured to store in Couchbase. Typically, this is JSON, but it can also be in other formats like JSON bytes or other byte arrays.

The reason why we look at the span, given it is a quick in-memory operation, is because of the time accrued here which can provide insights into the overall system performance. This duration should always be short. If it's not, there could be two main reasons:

• Resource Constraints: The SDK might be struggling to get the necessary resources (like CPU time, memory allocation, etc.) for the conversion. We've seen issues in deployments where virtual machines are over-committed or runtimes face memory or CPU pressure. These are hard to detect, but if we see spans with unusually long times for this operation, it indicates a potential resource issue.

• Complex or Large Objects: Sometimes, the objects being converted are very complex or large, which naturally takes more time. In such cases, the application developer can simplify the objects to speed up the process.

The Dispatch to Server Span

This span provides the time from when the SDK performs its I/O call, typically to a platform library, to when the response is received and decoded out of the protocol framing. This span, when returned, contains various information about the request (assuming full completion), such as the “hostname:port” the request was sent to and “db.couchbase.server_duration”.

Important note: This dispatch to the server can happen multiple times. One scenario is when we send a request to a server that is leaving the cluster, and it responds that the vbucket has moved. These instances are rare but can occur during topology changes. It may also happen if a network connection drops and it's safe for us to retry. Additionally, it can occur on some platforms where the retry handler is overridden.

It might be useful to look at a stack trace for a get operation served from the memory. Here’s an example in Java:

The SDK is abstracted across multiple layers, each of which can take varying amounts of time due to different factors.

The `server_duration` starts after the request is decoded from the network buffer and ends when the async I/O response is written. 

Let’s take an arbitrary get example, where we see 3 microseconds `server_duration` span and the 1.85 seconds `dispatch_to_server` spans:

The request spends some time in the device and then moves to a buffer in memory. The Data Service (or memcached) thread receives an event to process it. Within the memcached process, we run several thread pools. For our simple example, it's only the frontend thread pool. Each thread in this pool handles a certain number of connections. Since there are no I/O operations, the thread works with the particular connection and then switches to another connection to ensure fair processing.

At this point, it's worth noting the question about the gap between the “server_duration” and the “dispatch_to_server” spans. Typically, syscalls involving I/O (moving buffers from userspace to the kernel or vice versa) are on the order of tens of microseconds. Therefore, it's clear that the 3 microseconds is just the userspace processing outside any real syscalls.

We measure this “server_duration” because not all requests come from memory. We may need to ”backfill” an item. In that case, the frontend thread will set up the backfill and request an event to know when the data is available. Another thread will handle the backfill into the memory structure, completing the event. It may take some time since the frontend thread might be working with a different socket, but it will return to complete the I/O. We currently don't indicate whether the operation involved I/O or it was part of a transaction with multiple I/Os. These are considerations we can explore, but they need to fit within the tight protocol framing to remain efficient.

So, what can make “server_duration” high? Most of the time, we would expect it to be the I/O. However, there can be other causes. Rarely, this might be due to the frontend threads being very busy with many connections or handling a lot of authentication. The frontend thread can also be context-switched away, allowing the CPU to be used by another process for some time. It's even possible for hot locks unrelated to our front-end thread to take time.

Here's an example we've encountered a couple of times to give you a sense of what is possible. We've seen situations where a user sets up a resource monitor. One instance we recall distinctly involved OpenView, which was set up by the user to monitor system resources. OpenView would periodically scan the “/proc” filesystem to gather stats, preventing I/O events from reaching the Memcached process. At the client, we observed periodic latency spikes, approximately every 10 seconds. From the server processing perspective, it didn't appear the server was taking long (as this was an in-memory deployment). 

As this was before we had tracing, we verified that the slowness was on the server side through packet flow bisection from a span port on the switch, the server, and the client. In this case, the issue was in the kernel. The user reviewed the recent change control and found the new monitoring tool. This deployment inspired us to add tracing, as reviewing multiple packet captures is time-consuming and increasingly difficult with TLS.

Out of the Box Response Time Observability (RTO)

To provide something easy and on by default, we have also implemented an in-process tracer into the SDKs. This is added as many SDK users have not adopted tracing yet. This tracer gathers statistics that SDK logs at regular intervals. We also take advantage of the fact that the SDK often receives replies for operations that have already timed out or canceled.

Conclusion

In summary, tracing often helps us understand particular spans in processing, though it can't give us the full picture. We've tried to be thoughtful about these spans so we can aggregate the tracing in different ways to quickly understand where else to look, if not understand the full cause. Here are some examples from analysis focused on timeouts:

• Analysis: No orphan responses are received. The connection is eventually disrupted.
  • Likely cause: Network issues.
• Analysis: Some timeouts map to orphan responses, and all orphan responses are from one server. The topmost orphan response has a large server duration, and subsequent responses are fast (or become fast) with increasing opaques for this individual client log.
  • Likely cause: One slow operation caused congestion due to the lack of Out of Order Operations (feature in MB-10291, shipped in Server version 7.0) or other causes.
• Analysis: Only some timeouts map to orphan responses, and orphan responses are from multiple servers. Orphan responses have small server durations relative to the timeout value.
  • Likely cause: General environmental issues at the client, host VM/container, the network, or the servers, which are not severe enough to cause connection disruption.
• Analysis: Only some timeouts map to the orphan responses. Orphan responses are from one server and have small server durations relative to the timeout value.
  • Likely cause: An environmental problem (e.g. THP being enabled at the server in question).

References:

• RFC0035 - Response Time Observability