paste.httpserver et ralentissement avec HTTP / 1.1 Keep-alive; testé avec httperf et ab

Question

J'ai un serveur web basé sur paste.httpserver comme adapater entre HTTP et WSGI. Quand je fais des mesures de performance avec httperf, je peux faire plus de 1 000 demandes par seconde si je commence une nouvelle demande chaque fois à l'aide --num-Conn. Si je réutiliser au lieu de la connexion à l'aide --num appel alors je reçois environ 11 demandes par seconde, 1 / 100ème de la vitesse.

Si je tente ab je reçois un délai d'attente.

Mes tests sont

% ./httperf --server localhost --port 8080 --num-conn 100
...
Request rate: 1320.4 req/s (0.8 ms/req)
...

et

% ./httperf --server localhost --port 8080 --num-call 100
...
Request rate: 11.2 req/s (89.4 ms/req)
...

Voici un simple serveur reproductible

from paste import httpserver

def echo_app(environ, start_response):
    n = 10000
    start_response("200 Ok", [("Content-Type", "text/plain"),
                              ("Content-Length", str(n))])
    return ["*" * n]

httpserver.serve(echo_app, protocol_version="HTTP/1.1")

Il est un serveur multi-thread, qui est difficile à profil. Voici une variante qui est seul thread:

from paste import httpserver

class MyHandler(httpserver.WSGIHandler):
    sys_version = None
    server_version = "MyServer/0.0"
    protocol_version = "HTTP/1.1"

    def log_request(self, *args, **kwargs):
        pass


def echo_app(environ, start_response):
    n = 10000
    start_response("200 Ok", [("Content-Type", "text/plain"),
                              ("Content-Length", str(n))])
    return ["*" * n]

# WSGIServerBase is single-threaded
server = httpserver.WSGIServerBase(echo_app, ("localhost", 8080), MyHandler)
server.handle_request()

profileurs avec

% python2.6 -m cProfile -o paste.prof paste_slowdown.py

et frappant avec

%httperf --client=0/1 --server=localhost --port=8080 --uri=/ \ 
   --send-buffer=4096 --recv-buffer=16384 --num-conns=1 --num-calls=500

Je reçois un profil comme

>>> p=pstats.Stats("paste.prof")
>>> p.strip_dirs().sort_stats("cumulative").print_stats()
Sun Nov 22 21:31:57 2009    paste.prof

         109749 function calls in 46.570 CPU seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000   46.571   46.571 {execfile}
        1    0.001    0.001   46.570   46.570 paste_slowdown.py:2(<module>)
        1    0.000    0.000   46.115   46.115 SocketServer.py:250(handle_request)
        1    0.000    0.000   44.675   44.675 SocketServer.py:268(_handle_request_noblock)
        1    0.000    0.000   44.675   44.675 SocketServer.py:301(process_request)
        1    0.000    0.000   44.675   44.675 SocketServer.py:318(finish_request)
        1    0.000    0.000   44.675   44.675 SocketServer.py:609(__init__)
        1    0.000    0.000   44.675   44.675 httpserver.py:456(handle)
        1    0.001    0.001   44.675   44.675 BaseHTTPServer.py:325(handle)
      501    0.006    0.000   44.674    0.089 httpserver.py:440(handle_one_request)
     2001    0.020    0.000   44.383    0.022 socket.py:373(readline)
      501   44.354    0.089   44.354    0.089 {method 'recv' of '_socket.socket' objects}
        1    1.440    1.440    1.440    1.440 {select.select}
         ....

Vous pouvez voir que presque tout le temps est recv.

J'ai décidé de liberté sous caution le httpref et écrire mon propre HTTP / 1.1 avec-keep-alive demande et l'envoyer à l'aide netcat:

GET / HTTP/1.1
Location: localhost
Connection: Keep-Alive
Content-Length: 0

GET / HTTP/1.1
Location: localhost
Connection: Keep-Alive
Content-Length: 0

 ... repeat 97 more times, to have 99 keep-alives in total ...

GET / HTTP/1.1
Location: localhost
Connection: Close
Content-Length: 0

que j'ai envoyé avec

nc localhost 8080 < ~/src/send_to_paste.txt

Temps total pour 100 demandes a été de 0,03 secondes, il est donc très bonne performance.

Ceci suggère que httperf fait quelque chose de mal (mais il est un morceau de code largement utilisé et respecté), alors j'ai essayé « ab »

% ab -n 100 -k localhost:8080/
This is ApacheBench, Version 1.3d <$Revision: 1.73 $> apache-1.3
Copyright (c) 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Copyright (c) 2006 The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)...
Server timed out

: Operation now in progress

Instrumentation de serveur, il gère une demande et attend le second.

Toute idée de ce qui se passe?

Answer 1

Après un certain effort, il semble être soit algorithme de Nagle ou l'ACK retardé, ou les interactions entre eux. Il en va si je fais quelque chose comme

server.socket.setsockopt(socket.IPPROTO_TCP, socket.TCP_NODELAY, 1)

Comment ai-je le suivre vers le bas? Tout d'abord, j'instrumenté tous les « recv » dans socket.py, pour que je puisse comprendre ce qui recv attendait. Je verrais environ 5 out de recv de 11 avait un retard de près de 200 ms. Je ne pouvais pas comprendre pourquoi il y avait un retard. J'ai ensuite utilisé Wireshark pour regarder les messages et a remarqué que l'on était en fait l'envoi du serveur au client qui avait le retard. Cela voulait dire quelque chose dans la couche TCP dans les messages sortants de mon client.

Un ami a suggéré l'évidence, et je cherchais « retard de prise de 200ms » et a trouvé des descriptions de ce problème.

Le rapport de la pâte est de trac http://trac.pythonpaste.org/pythonpaste/ticket/ 392 ainsi un patch qui permet TCP_NODELAY lorsque le gestionnaire utilise le protocole HTTP / 1.1.