Locate the cause of high response latency by using access logs - Alibaba Cloud Service Mesh

Sidecar proxies injected into workloads intercept and route traffic based on configured policies. Each proxy adds a small amount of processing time, though this overhead is negligible for concurrent processing when nodes have adequate resources.

When response latency is higher than expected, access log timing fields help you isolate the cause. The process has two steps:

Identify which component in the request path introduces the latency.
Determine whether the root cause is slow network transmission or slow upstream processing.

Prerequisites

Before you begin, make sure that:

Access logging is enabled for your ASM instance. For more information, see Enable access log collection.
You can retrieve sidecar proxy logs by running kubectl logs <pod-name> -c istio-proxy -n <namespace>.

How access log timing fields work

Each data plane component (sidecar proxy or gateway) records timing fields in its access log entry. These fields measure different segments of the request lifecycle:

                          Request lifecycle at a single data plane component

  Downstream                    Data plane component                    Upstream
  (client)                    (sidecar proxy / gateway)                 (service)
     |                                   |                                  |
     |-------- request_duration -------->|                                  |
     |   (start -> last byte received   |                                  |
     |    from downstream)              |                                  |
     |                                  |-------- request_tx_duration ----->|
     |                                  |   (start -> last byte sent       |
     |                                  |    to upstream)                   |
     |                                  |                                   |
     |                                  |<--- response_duration ------------|
     |                                  |   (start -> first byte received  |
     |                                  |    from upstream)                 |
     |                                  |                                   |
     |<-------- response_tx_duration ---|                                   |
     |   (first byte received from      |                                  |
     |    upstream -> last byte sent    |                                  |
     |    to downstream)               |                                  |
     |                                  |                                   |

     |<===================== duration =================================>|
                        (start -> last byte out)

Field	What it measures	From	To
`duration`	Total request-response cycle	Request start	Last byte sent to downstream
`request_duration`	Full request received from downstream	Request start	Last byte of request received from downstream
`request_tx_duration`	Full request transmitted to upstream	Request start	Last byte of request sent to upstream
`response_duration`	Time to first response byte from upstream	Request start	First byte of response received from upstream
`response_tx_duration`	Full response delivered to downstream	First byte of response received from upstream	Last byte of response sent to downstream

Sample access log comparison

The following example shows timing fields from the client-side sidecar and the server-side sidecar for the same request. Comparing values across both sides helps you pinpoint where latency occurs.

Field	Client-side sidecar	Server-side sidecar	Interpretation
`duration`	250 ms	30 ms	The client-side component accounts for most of the latency.
`request_duration`	5 ms	2 ms	Request was received quickly on both sides.
`request_tx_duration`	200 ms	3 ms	The client-side proxy took a long time to forward the request to upstream, suggesting network issues between the two sidecars.
`response_duration`	220 ms	25 ms	Difference is consistent with slow request transmission from the client side.
`response_tx_duration`	30 ms	5 ms	Response delivery was relatively fast on both sides.

Step 1: Identify the component that introduces latency

Check the duration field in the access log of each component along the request path. This value represents the total time the component spent receiving the request, forwarding it upstream, waiting for the response, and sending the response back downstream.

Compare duration values across components in the request path:

Start at the entry point (gateway or first sidecar proxy) and note its duration.
Check the next upstream component's duration.
- If the upstream component's duration is within the expected range, the current component is the source of excess latency.
- If the upstream component's duration is also higher than expected, move one hop further upstream and repeat the comparison.
Continue until you find the component where latency drops to normal levels. The component immediately downstream of it is the one introducing excess latency.

Step 2: Determine the root cause

After you identify the component, examine its access log fields to distinguish between two root causes: slow network transmission and slow upstream processing.

Slow network transmission

Check request_duration and request_tx_duration:

High request_duration -- The component took a long time to receive the request from the downstream node, indicating network issues between the downstream node and this component (sidecar proxy or gateway).
High request_tx_duration -- The component took a long time to forward the request to the upstream service, indicating network issues between this component and the upstream service.

For HTTP requests with a body, the component reads and forwards the body simultaneously rather than buffering it entirely before forwarding. As a result, a high request_duration often causes a correspondingly high request_tx_duration. If only request_tx_duration is high while request_duration is normal, the request was received quickly but forwarded slowly to the upstream service.

Check request_duration and response_tx_duration together for response-path issues:

If both request_duration and response_tx_duration are high, the response was either read slowly from the upstream service or forwarded slowly to the downstream node.

Slow upstream processing

Compare response_duration and request_tx_duration:

The difference between these two values approximates the time the upstream service spent processing the request:

Upstream processing time ≈ response_duration - request_tx_duration

A large difference indicates that the upstream service is slow to process the request or that there is high network latency between the component and the upstream service.

Quick reference: field patterns and likely causes

Field pattern	Likely cause	Next step
High `request_duration`	Slow network between downstream and current component	Check downstream node network, packet loss, and bandwidth.
High `request_tx_duration` only	Slow network between current component and upstream	Check upstream network path and DNS resolution.
High `request_duration` + high `request_tx_duration`	Slow downstream network (cascading effect from body streaming)	Focus on the downstream network path.
High `request_duration` + high `response_tx_duration`	Slow response read from upstream or slow forwarding to downstream	Check response path network and upstream service health.
High `response_duration` - `request_tx_duration`	Slow upstream processing or high upstream network latency	Profile the upstream service and check upstream resource usage.
High `response_tx_duration`	Slow response delivery to downstream	Check response size and downstream network capacity.