paste.httpserver y desaceleración con HTTP / 1.1 keep-alive; probado con httperf y ab
-
21-09-2019 - |
Pregunta
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?
Solución
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.