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

Los proxies sidecar inyectados en las cargas de trabajo interceptan y enrutan el tráfico según las directivas configuradas. Cada proxy añade una pequeña cantidad de tiempo de procesamiento, aunque esta sobrecarga es insignificante para el procesamiento simultáneo cuando los nodos cuentan con recursos adecuados.

Cuando la latencia de respuesta es mayor a la esperada, los campos de tiempo en los registros de acceso ayudan a aislar la causa. El proceso consta de dos pasos:

Identificar qué componente en la ruta de la solicitud introduce la latencia.
Determinar si la causa raíz es una transmisión de red lenta o un procesamiento lento en el upstream.

Requisitos previos

Antes de empezar, asegúrese de que:

El registro de acceso está habilitado para su instancia de ASM. Para obtener más información, consulte Enable access log collection.
Puede recuperar los registros del proxy sidecar al ejecutar kubectl logs <pod-name> -c istio-proxy -n <namespace>.

Funcionamiento de los campos de tiempo en los registros de acceso

Cada componente del plano de datos (proxy sidecar o gateway) registra campos de tiempo en su entrada de registro de acceso. Estos campos miden diferentes segmentos del ciclo de vida de la solicitud:

                          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)

Campo	Qué mide	Desde	Hasta
`duration`	Ciclo completo de solicitud-respuesta	Inicio de la solicitud	Último byte enviado al downstream
`request_duration`	Solicitud completa recibida del downstream	Inicio de la solicitud	Último byte de la solicitud recibido del downstream
`request_tx_duration`	Solicitud completa transmitida al upstream	Inicio de la solicitud	Último byte de la solicitud enviado al upstream
`response_duration`	Tiempo hasta el primer byte de respuesta del upstream	Inicio de la solicitud	Primer byte de respuesta recibido del upstream
`response_tx_duration`	Respuesta completa entregada al downstream	Primer byte de respuesta recibido del upstream	Último byte de respuesta enviado al downstream

Comparación de ejemplo de registros de acceso

El siguiente ejemplo muestra los campos de tiempo del sidecar del lado del cliente y del sidecar del lado del servidor para la misma solicitud. La comparación de valores entre ambos lados ayuda a identificar con precisión dónde ocurre la latencia.

Campo	Sidecar del lado del cliente	Sidecar del lado del servidor	Interpretación
`duration`	250 ms	30 ms	El componente del lado del cliente representa la mayor parte de la latencia.
`request_duration`	5 ms	2 ms	La solicitud se recibió rápidamente en ambos lados.
`request_tx_duration`	200 ms	3 ms	El proxy del lado del cliente tardó mucho en reenviar la solicitud al upstream, lo que sugiere problemas de red entre los dos sidecars.
`response_duration`	220 ms	25 ms	La diferencia coincide con una transmisión lenta de la solicitud desde el lado del cliente.
`response_tx_duration`	30 ms	5 ms	La entrega de la respuesta fue relativamente rápida en ambos lados.

Paso 1: Identificación del componente que introduce la latencia

Revise el campo duration en el registro de acceso de cada componente a lo largo de la ruta de la solicitud. Este valor representa el tiempo total que el componente dedicó a recibir la solicitud, reenviarla al upstream, esperar la respuesta y enviarla de vuelta al downstream.

Compare los valores de duration entre los componentes de la ruta de solicitud:

Comience en el punto de entrada (gateway o primer proxy sidecar) y anote su valor de duration.
Verifique el valor de duration del siguiente componente en el upstream.
- Si el valor de duration del componente upstream se encuentra dentro del rango esperado, el componente actual es la fuente del exceso de latencia.
- Si el valor de duration del componente upstream también es mayor al esperado, avance un salto más hacia el upstream y repita la comparación.
Continúe hasta encontrar el componente donde la latencia desciende a niveles normales. El componente inmediatamente posterior (downstream) a este es el que introduce el exceso de latencia.

Paso 2: Determinación de la causa raíz

Una vez identificado el componente, examine sus campos de registro de acceso para distinguir entre dos causas raíz: transmisión de red lenta y procesamiento lento en el upstream.

Transmisión de red lenta

Revise request_duration y request_tx_duration:

**Valor alto de request_duration**: El componente tardó mucho en recibir la solicitud del nodo downstream, lo que indica problemas de red entre dicho nodo y este componente (proxy sidecar o gateway).
**Valor alto de request_tx_duration**: El componente tardó mucho en reenviar la solicitud al servicio upstream, lo que indica problemas de red entre este componente y el servicio upstream.

En solicitudes HTTP con cuerpo, el componente lee y reenvía el cuerpo simultáneamente en lugar de almacenarlo por completo antes de reenviarlo. Como resultado, un valor alto de request_duration suele provocar un valor proporcionalmente alto de request_tx_duration . Si solo request_tx_duration es alto mientras que request_duration es normal, significa que la solicitud se recibió rápidamente pero se reenvió lentamente al servicio upstream.

Revise conjuntamente request_duration y response_tx_duration para detectar problemas en la ruta de respuesta:

Si **tanto request_duration como response_tx_duration** son altos, la respuesta se leyó lentamente del servicio upstream o se reenvió lentamente al nodo downstream.

Procesamiento lento en el upstream

Compare response_duration y request_tx_duration:

La diferencia entre estos dos valores aproxima el tiempo que el servicio upstream dedicó a procesar la solicitud:

Upstream processing time ≈ response_duration - request_tx_duration

Una diferencia grande indica que el servicio upstream tarda en procesar la solicitud o que existe una alta latencia de red entre el componente y el servicio upstream.

Referencia rápida: patrones de campos y causas probables

Patrón de campo	Causa probable	Siguiente paso
Valor alto de `request_duration`	Red lenta entre el downstream y el componente actual	Compruebe la red del nodo downstream, la pérdida de paquetes y el ancho de banda.
Solo valor alto de `request_tx_duration`	Red lenta entre el componente actual y el upstream	Verifique la ruta de red hacia el upstream y la resolución DNS.
Valor alto de `request_duration` + valor alto de `request_tx_duration`	Red downstream lenta (efecto en cascada por streaming del cuerpo)	Enfóquese en la ruta de red del downstream.
Valor alto de `request_duration` + valor alto de `response_tx_duration`	Lectura lenta de respuesta del upstream o reenvío lento al downstream	Compruebe la red de la ruta de respuesta y el estado del servicio upstream.
Valor alto de `response_duration` - `request_tx_duration`	Procesamiento lento en el upstream o alta latencia de red hacia el upstream	Analice el perfil del servicio upstream y verifique el uso de recursos en el upstream.
Valor alto de `response_tx_duration`	Entrega lenta de respuesta al downstream	Verifique el tamaño de la respuesta y la capacidad de la red downstream.