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

Les proxys sidecar injectés dans les charges de travail interceptent et acheminent le trafic selon les politiques configurées. Chaque proxy ajoute un léger temps de traitement, mais cette surcharge reste négligeable lors du traitement simultané si les nœuds disposent de ressources suffisantes.

Si la latence de réponse est plus élevée que prévu, les champs de temporisation des journaux d'accès vous aident à en isoler la cause. La procédure comprend deux étapes :

Identifiez le composant du chemin de requête qui introduit la latence.
Déterminez si la cause racine réside dans une transmission réseau lente ou un traitement amont lent.

Prérequis

Avant de commencer, assurez-vous que :

La journalisation d'accès est activée pour votre instance ASM. Pour plus d'informations, consultez la rubrique Enable access log collection.
Récupérez les journaux du proxy sidecar en exécutant kubectl logs <pod-name> -c istio-proxy -n <namespace>.

Fonctionnement des champs de temporisation des journaux d'accès

Chaque composant du plan de données (proxy sidecar ou passerelle) enregistre des champs de temporisation dans son entrée de journal d'accès. Ces champs mesurent différentes phases du cycle de vie de la requête :

                          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)

Champ	Mesure	De	À
`duration`	Cycle complet requête-réponse	Début de la requête	Dernier octet envoyé au client aval
`request_duration`	Réception complète de la requête depuis le client aval	Début de la requête	Dernier octet de la requête reçu du client aval
`request_tx_duration`	Transmission complète de la requête vers le service amont	Début de la requête	Dernier octet de la requête envoyé au service amont
`response_duration`	Temps jusqu'au premier octet de réponse du service amont	Début de la requête	Premier octet de la réponse reçu du service amont
`response_tx_duration`	Livraison complète de la réponse au client aval	Premier octet de la réponse reçu du service amont	Dernier octet de la réponse envoyé au client aval

Exemple de comparaison des journaux d'accès

L'exemple suivant présente les champs de temporisation du sidecar côté client et du sidecar côté serveur pour la même requête. Comparez les valeurs des deux côtés pour identifier précisément l'origine de la latence.

Champ	Sidecar côté client	Sidecar côté serveur	Interprétation
`duration`	250 ms	30 ms	Le composant côté client représente la majeure partie de la latence.
`request_duration`	5 ms	2 ms	La requête a été reçue rapidement des deux côtés.
`request_tx_duration`	200 ms	3 ms	Le proxy côté client a mis beaucoup de temps à transférer la requête vers le service amont, ce qui suggère des problèmes réseau entre les deux sidecars.
`response_duration`	220 ms	25 ms	La différence est cohérente avec une transmission lente de la requête depuis le côté client.
`response_tx_duration`	30 ms	5 ms	La livraison de la réponse était relativement rapide des deux côtés.

Étape 1 : Identifier le composant qui introduit la latence

Vérifiez le champ duration dans le journal d'accès de chaque composant le long du chemin de requête. Cette valeur représente le temps total passé par le composant à recevoir la requête, à la transférer vers le service amont, à attendre la réponse et à renvoyer la réponse au client aval.

Comparez les valeurs de duration entre les composants du chemin de requête :

Commencez au point d'entrée (passerelle ou premier proxy sidecar) et notez sa valeur duration.
Vérifiez la valeur duration du composant amont suivant.
- Si la valeur duration du composant amont se situe dans la plage attendue, le composant actuel est la source de la latence excessive.
- Si la valeur duration du composant amont est également supérieure à la normale, remontez d'un saut supplémentaire vers l'amont et répétez la comparaison.
Poursuivez jusqu'à trouver le composant où la latence revient à un niveau normal. Le composant situé immédiatement en aval de celui-ci est celui qui introduit la latence excessive.

Étape 2 : Déterminer la cause racine

Une fois le composant identifié, examinez ses champs de journal d'accès pour distinguer deux causes racines : une transmission réseau lente et un traitement amont lent.

Transmission réseau lente

Vérifiez les champs request_duration et request_tx_duration :

**Valeur élevée de request_duration** : le composant a mis beaucoup de temps à recevoir la requête du nœud aval, ce qui indique des problèmes réseau entre le nœud aval et ce composant (proxy sidecar ou passerelle).
**Valeur élevée de request_tx_duration** : le composant a mis beaucoup de temps à transférer la requête au service amont, ce qui indique des problèmes réseau entre ce composant et le service amont.

Pour les requêtes HTTP avec un corps, le composant lit et transfère le corps simultanément plutôt que de le mettre entièrement en mémoire tampon avant le transfert. Par conséquent, une valeur élevée de request_duration entraîne souvent une valeur correspondamment élevée de request_tx_duration . Si seule la valeur de request_tx_duration est élevée tandis que celle de request_duration est normale, la requête a été reçue rapidement mais transférée lentement au service amont.

Vérifiez conjointement les champs request_duration et response_tx_duration pour détecter les problèmes liés au chemin de réponse :

Si **les valeurs de request_duration et de response_tx_duration sont toutes deux élevées**, la réponse a été soit lue lentement depuis le service amont, soit transférée lentement vers le nœud aval.

Traitement amont lent

Comparez les champs response_duration et request_tx_duration :

La différence entre ces deux valeurs approxime le temps passé par le service amont à traiter la requête :

Upstream processing time ≈ response_duration - request_tx_duration

Une différence importante indique que le service amont traite la requête lentement ou qu'il existe une latence réseau élevée entre le composant et le service amont.

Référence rapide : modèles de champs et causes probables

Modèle de champ	Cause probable	Étape suivante
Valeur élevée de `request_duration`	Réseau lent entre le client aval et le composant actuel	Vérifiez le réseau du nœud aval, la perte de paquets et la bande passante.
Valeur élevée de `request_tx_duration` uniquement	Réseau lent entre le composant actuel et le service amont	Vérifiez le chemin réseau amont et la résolution DNS.
Valeur élevée de `request_duration` + valeur élevée de `request_tx_duration`	Réseau aval lent (effet en cascade dû au streaming du corps)	Concentrez-vous sur le chemin réseau aval.
Valeur élevée de `request_duration` + valeur élevée de `response_tx_duration`	Lecture lente de la réponse depuis le service amont ou transfert lent vers le client aval	Vérifiez le réseau du chemin de réponse et l'état du service amont.
Valeur élevée de `response_duration` - `request_tx_duration`	Traitement amont lent ou latence réseau amont élevée	Profilez le service amont et vérifiez l'utilisation des ressources amont.
Valeur élevée de `response_tx_duration`	Livraison lente de la réponse au client aval	Vérifiez la taille de la réponse et la capacité du réseau aval.