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

Les proxies 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 en cas de traitement simultané lorsque les nœuds disposent de ressources suffisantes.

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

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

Prérequis

Avant de commencer, vérifiez que :

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

Fonctionnement des champs temporels des journaux d'accès

Chaque composant du plan de données (proxy sidecar ou passerelle) enregistre des champs temporels 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	Ce qu'il mesure	De	À
`duration`	Cycle complet requête-réponse	Début de la requête	Dernier octet envoyé au client (downstream)
`request_duration`	Réception complète de la requête depuis le client (downstream)	Début de la requête	Dernier octet de la requête reçu du client (downstream)
`request_tx_duration`	Transmission complète de la requête vers le service amont (upstream)	Début de la requête	Dernier octet de la requête envoyé au service amont (upstream)
`response_duration`	Temps écoulé jusqu'au premier octet de réponse du service amont (upstream)	Début de la requête	Premier octet de la réponse reçu du service amont (upstream)
`response_tx_duration`	Livraison complète de la réponse au client (downstream)	Premier octet de la réponse reçu du service amont (upstream)	Dernier octet de la réponse envoyé au client (downstream)

Exemple de comparaison des journaux d'accès

L'exemple suivant présente les champs temporels 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 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 situé sur le chemin de la 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 (downstream).

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

Commencez par le point d'entrée (passerelle ou premier proxy sidecar) et notez sa valeur de duration.
Vérifiez la valeur de duration du composant amont suivant.
- Si la valeur de duration du composant amont se situe dans la plage attendue, le composant actuel est la source de la latence excessive.
- Si la valeur de duration du composant amont est également supérieure aux attentes, remontez d'un cran 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 en aval (downstream), ce qui indique des problèmes réseau entre le nœud en 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 (upstream), 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 sur le chemin de la 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 au nœud en 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 pour traiter la requête :

Upstream processing time ≈ response_duration - request_tx_duration

Une différence importante indique que le service amont est lent à traiter la requête 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 nœud en aval et le composant actuel	Vérifiez le réseau du nœud en 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 en aval lent (effet en cascade dû au streaming du corps)	Concentrez-vous sur le chemin réseau en 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 nœud en 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 nœud en aval	Vérifiez la taille de la réponse et la capacité du réseau en aval.