Forum général.général Apache et ses logs

Posté par  (site web personnel) .
Étiquettes :
0
30
août
2011

Bonjour,

Je suis sûr que parmis toi, lecteur, se cache un Apache Killer.

Préambule

Le choix des logiciels a été mûrement réfléchi et il n'est pas question d'en changer (en plus c'est pas le sujet).

Infrastructure

Network

Internet/RadianZ/Swift (filtrage IP+quelques blackBox) --> Dmz Outter --> Dmz Inner --> Trusted Zone --> Zone non nommée (DB + MainFrame)
A noter de l'affinité de session entre chaque couche.

Soft

Dmz Outter : Reverse Proxy Servers (Apache mod_proxy_http, mod_rewrite + autres)
Dmz Inner : Web Servers (Apache + Module propriétaire[¹])
Trusted : Server d'Application (propriétaire[²])
Plus loin : Hors sujet

Flux

La requête arrive sur le RP (qui traite ou envoi dans le mur) passe la main au WS qui transfère au SA (qui fait ses traitements, etc.).
A noter aussi les ruptures de protocol (après la DMZ Inner et les mutual authentication entre chaque couche).

Problème

Les logs Apache sont tous des custom et contiennent tous un %D à la fin.

Soit une requête qui traverse les différentes couches et qui retourne 1071 octets de données :
Sur le RP le temps d'une requête est 2582904µs
Sur le WS le temps d'une requête est 2578351µs
Sur le SA le temps d'une requête est 1003254µs
Mes questions sont :
* Qui me ment ?
* Apache bufferise-t-il ce qui lui vient de plus loin avant de le renvoyer ou le renvoie-t-il au fil de l'eau ?
* Le temps indiqué dans les logs indique-t-il :
** du début de la requête jusqu'à ce que le dernier octet soit renvoyé et la connexion clôturée ?
** du début de la requête jusqu'à ce que le premier octet soit renvoyé ?
* D'où peut venir cette latence ?
* Si en amont de mes RPs le débit/latence est pourrave cela peut-il faire que le RP molassonne mon WS ?

Merci pour vos réponses.

[¹] : Ca ressemble un peu au plugin IHS pour WebSphere pour ceux qui connaissent. Bref, dans le fonctionnement, on dirait un Reverse proxy qui fait du rewrite...
[²] : Ca ressemble un peu à WebSphere, sauf que ça ne gère absolument pas du Java et en plus c'est pas stable...

  • # c'est des math

    Posté par  . Évalué à 4.

    Soit une requête qui traverse les différentes couches et qui retourne 1071 octets de données :
    Sur le RP le temps d'une requête est 2582904µs
    Sur le WS le temps d'une requête est 2578351µs
    Sur le SA le temps d'une requête est 1003254µs

    dans ton enoncé tu dis que la requete suit le trajet suivant
    Client -> RP -> WS -> SA

    donc le calcul est bon :
    l'appli (SA) recoit la requete et la traite en 1.003.254µs

    puis donne le resultat à WS qui etait en attente, WS obtient donc un reponse à 2.578.351µs (transmission WS->SA + traitement 1.003.254 + transmission SA->WS)

    puis passe le resultat à RP qui attendait et qui te dit que de son point de vue la requete à mis 2.582.904µs (trans RP ->WS + trans WS -> SA + traitement + trans SA -> WS + trans WS -> RP)

    • [^] # Re: c'est des math

      Posté par  (site web personnel) . Évalué à 0.

      Ma question est plus sur comment est calculé le temps par Apache...

      J'ai deux représentations :

      1. Ecriture de logs post requêtes [¹]

      Ecriture de logs post requêtes

      2. Ecriture de logs avant fin requêtes [²]

      Ecriture de logs avant fin requêtes

      Dans le cas 1, il me parait logique de dire que j'ai une latence (~1 seconde) entre le WS et le SA.
      Dans le cas 2, ça me pose plus de problème, car il peut s'agir du WS, du RP, ou du réseau (et la ça dépend si Apache bufferise ou s'il renvoie au fil de l'eau).

      Ma question est-elle plus compréhensible ?

      [¹] Pour correction si besoin - [²] Pour correction si besoin

      • [^] # Re: c'est des math

        Posté par  . Évalué à 1.

        Non. Le jeu des différences c'est pas drôle.

        Je comprends bien le premier shéma mais j'ai l'impression que le deuxième c'est le même (et que ça devrait pas).

        • [^] # Re: c'est des math

          Posté par  (site web personnel) . Évalué à 0.

          En fait dans le deuxième, je me pose la questino de savoir si logs ne sopnt pas écrits juste avant la réponse faite au layer du dessus.

      • [^] # Re: c'est des math

        Posté par  . Évalué à 2.

        perso je penses que le cas n° 2 ne peut pas arriver (ecriture du log avant la fin de la requete, vu qu'il a besoin de connaitre le resultat du temps de la requete pour ecrire dans le log)

        apres, tu t'en fous du buffer car c'est pas l'ecriture dans le log qui declenche la transmission des données vers le "client"

        enfin comme le dit notre ami au dessus, je ne vois pas de difference entre les deux schemas

        • [^] # Re: c'est des math

          Posté par  . Évalué à 2.

          j'ai cliqué sur envoyer, alors que je chercher la difference entre les deux schemas, et elle y est bien, c'est dans la fleche "result" qui est avant ou apres "ecriture logs"

  • # Très cohérent

    Posté par  . Évalué à 3.

    Je ne comprends pas ce qui te dérange.
    > Qui me ment ?

    Personne, on a bien 2582904µs > 2578351µs > 1003254µs

    Apache bufferise-t-il ce qui lui vient de plus loin avant de le renvoyer ou le renvoie-t-il au fil de l'eau ?

    Il bufferise dans une certaine mesure. Le reverse-proxy n'est pas un switch ou un équipement réseau de niveau IP. Lorsqu'il reçoit une requête, il la traite, et il créer une NOUVELLE requête vers le serveur suivant. La bufferisation dépends de la version d'apache et du protocole HTTP utilisé pour chaque liaison (tu as 3 requêtes HTTP différentes). Regarde en particulier le mode chunked de HTTP/1.1. Si tu as un filtre de sortie, genre compression, ça augmente les besoins de bufferisation.

    Le temps indiqué dans les logs indique-t-il :
    - du début de la requête jusqu'à ce que le dernier octet soit renvoyé et la connexion clôturée ?
    - du début de la requête jusqu'à ce que le premier octet soit renvoyé ?

    C'est le temps depuis l'arrivée de la requête jusqu'au moment où toute la réponse est partie dans la couche réseau et que Apache est en train de logger la ligne. Ça se passe ligne 650 de http://svn.apache.org/viewvc/httpd/httpd/tags/2.2.20/modules/loggers/mod_log_config.c?revision=1163057&view=markup

    D'où peut venir cette latence ?

    Chaque serveur doit parser la requête qu'il reçoit, appliquer un certain nombre de règles, se connecter au serveur suivant, envoyer sa requête. Dans le pire des cas, il peut avoir un filtre sur la sortie, genre une compression, ou des entêtes à calculer, comme la taille de la réponse.

    Si en amont de mes RPs le débit/latence est pourrave cela peut-il faire que le RP molassonne mon WS ?

    Pas sur quelques Ko, parce que l'OS fait tampon, mais il est facile de montrer qu'a partir de quelques dizaines ou centaines de Ko, si le RP est bloqué sur une émission vers le navigateur, il ne va pas lire ce qui est arrivé du serveur (l'OS réduit la fenêtre TCP jusqu'à 0 si nécessaire), et toute la chaine ralentie.

    Le test est facile à faire, gdb permet d'aller de syscall en syscall (commande "catch syscall" puis "continue" pour avancer) pour ralentir la lecture des paquets. Faire envoyer un gros fichier d'un nc à un autre sur le localhost. Un tcpdump montre bien que la fenêtre TCP tombe à 0, on constate aussi que l’émetteur est bloqué tant que le récepteur ne lit pas de données.

Suivre le flux des commentaires

Note : les commentaires appartiennent à celles et ceux qui les ont postés. Nous n’en sommes pas responsables.