paste.httpserver y desaceleración con HTTP / 1.1 keep-alive; probado con httperf y ab

Question

Tengo un servidor web basado en paste.httpserver como adapater entre HTTP y WSGI. Cuando lo haga mediciones de rendimiento con httperf, no puedo hacer más de 1.000 solicitudes por segundo si comienzo a una nueva solicitud usando cada vez --num-Conn. Si en lugar reutilizar la conexión usando --num llamada entonces consigo cerca de 11 solicitudes por segundo, 1 / 100th de la velocidad.

Si intento ab consigo un tiempo de espera.

Mis pruebas son

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

y

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

Aquí hay un servidor reproducibles sencilla

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")

Es un servidor multi-hilo, que es difícil de perfil. Aquí hay una variación que es de un solo subproceso:

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()

Perfiles de que con

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

y golpeándola con

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

Me conseguir un perfil como

>>> 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}
         ....

Se puede ver que casi todo el tiempo está en un recv.

decidí rescatar en httpref y escribir mi propia HTTP / 1.1-con-keep-alive solicitud y enviarlo utilizando 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 envié con

nc localhost 8080 < ~/src/send_to_paste.txt

El tiempo total de 100 solicitudes fue de 0,03 segundos, por lo que es muy buen rendimiento.

Esto sugiere que httperf está haciendo algo mal (pero es un ampliamente utilizado y respetado pieza de código), así que traté '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

Instrumentación de servidor, se maneja una petición y está a la espera para el segundo.

Cualquier idea de lo que está pasando?

Answer 1

Después de un poco de esfuerzo, parece ser algoritmo de Nagle o el ACK retrasado, o las interacciones entre ellos. Desaparece si no hago algo así como

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

¿Cómo puedo realizar un seguimiento hacia abajo? En primer lugar, todos los instrumentado 'recv' en socket.py, por lo que pude averiguar qué recv estaba esperando. Me gustaría ver a cabo sobre 5 de recv del 11 tuvo un retraso de casi 200ms. No podía entender por qué no había ningún retraso. Luego utiliza Wireshark para ver los mensajes y se dio cuenta de que la realidad fue el envío desde el servidor al cliente que tenía el retraso. Eso significaba algo en la capa TCP en los mensajes salientes de mi cliente.

Un amigo le sugirió lo obvio, y yo buscaba "retardo de 200 ms socket" y encontró la descripción de este problema.

El informe de pasta de trac es en http://trac.pythonpaste.org/pythonpaste/ticket/ 392 junto con un parche que permite TCP_NODELAY cuando los usos de controlador de HTTP / 1.1.