Tracing Lettuce, Command Duration - What does it really measure?

[SimoneGiusso]

I didn't find any reference explaining exactly what the duration specified in the trace, really indicates. I'm trying to analyze some slow http requests, and I see some MGET redis requests taking even 750 ms to run. But what this duration includes? This is what I suppose it includes:

• Network Latency: Time for the request to travel from the client to the server and back.

• Server Processing Time: Time taken by the server to process the request (in this case, the /assets/discover endpoint).

• Database or Cache Access Time: If the operation involves querying a database or a cache (e.g., Redis), the time spent on these operations is also included.

• Application Logic: Any time taken by the application in handling the request, like reading from the socket and deserialize the response.

I'm not sure about the last one. But what I like to know is, if I can exclude at least latencies coming from the app. So I can be sure the app is not the problem. Otherwise the trace is not helping much. Too many variables to consider.

[tishun]

Hope this late answer will help.

There are quite some unknowns about your deployment for me to answer with confidence. Each of these span reports trace the execution of a single command. It starts the trace when the command is issued

public class CommandHandler extends ChannelDuplexHandler implements HasQueuedCommands {
    ...
    private void attachTracing(ChannelHandlerContext ctx, RedisCommand<?, ?, ?> command) {
    ...

... and then ends when the response is received by the driver ...

public class BraveTracing implements Tracing {
    ...
        @Override
        public BraveSpan start(RedisCommand<?, ?, ?> command) {
            span.name(command.getType().toString());
            ...
            if (command instanceof CompleteableCommand) {
                ...
                    span.finish();
                });
            } else {
                throw new IllegalArgumentException("Command " + command
                        + " must implement CompleteableCommand to attach Span completion to command completion");
            }

            span.start();
            this.tracingOptions.customizeSpan(command, span);

            return this;
        }
    ...

... depending on the type of the command and the settings for tracing.

On your questions, specifically:

Network Latency: Time for the request to travel from the client to the server and back.

Not sure of your architecture. Assuming the client is where the Lettuce driver is used and the server is where the Redis server is deployed, then yes.

Server Processing Time: Time taken by the server to process the request (in this case, the /assets/discover endpoint).

Probably not. /assets/discover is a REST endpoint? Served by some application (e.g. Spring boot)? The lettuce driver is part of this application? If yes to all three then - no. The timer starts when the driver makes the RESP request to the Redis server and this is after the REST request is handled by Spring.

Database or Cache Access Time: If the operation involves querying a database or a cache (e.g., Redis), the time spent on these operations is also included.

Probably yes. Lettuce makes RESP (RESP2 or RESP3) requests to Redis servers. The calculated time includes the time needed for the Redis server to process and respond to the MGET command. Querying other databases is not calculated. Only the time that was spend getting a response from Redis.

Application Logic: Any time taken by the application in handling the request, like reading from the socket and deserialize the response.

If the application uses Lettuce to handle the request, then yes.

Does that help?

[SimoneGiusso]

The application uses the lettuce java client to interact with the Redis server. So to summarize:

• Start time = instant the command is issued.
• End time = instant the answer is deserialized

Is it not possible to isolate the serialization and from the network latency + server process time?

[tishun]

The application uses the lettuce java client to interact with the Redis server. So to summarize:

• Start time = instant the command is issued.
• End time = instant the answer is deserialized

Yes. Assuming you are using asynchronous / reactive commands.

Is it not possible to isolate the serialization and from the network latency + server process time?

As far as I can tell - no. Do you need the serialization metrics specifically?

[SimoneGiusso]

I'd like to isolate the latency coming from the app (e.g. deserialization process) from what happens outside: network + server process. Having the duration of the MGET command containing all these metrics at once is not as useful as isolating the various components involved. As a user I would expect that the duration of the MGET command doesn't include any processing done by the app.

You answered at my initial question though. Thank you.

[tishun]

I'd like to isolate the latency coming from the app (e.g. deserialization process) from what happens outside: network + server process. Having the duration of the MGET command containing all these metrics at once is not as useful as isolating the various components involved. As a user I would expect that the duration of the MGET command doesn't include any processing done by the app.

You answer at my initial question though. Thank you.

I think having the serialization as a separate metric makes sense. If you want us to follow up with a feature please log a feature issue and we will put it in the backlog and prioritize it.

There is also the possibility of the community contributing the change.