paste.httpserver und Verlangsamung mit HTTP / 1.1 Keep-alive; getestet mit httperf und ab

Question

ich einen Web-Server basierend auf paste.httpserver als adapater zwischen HTTP und WSGI haben. Wenn ich die Leistung tue Messungen mit httperf, kann ich 1.000 Anfragen pro Sekunde tun über, wenn ich eine neue Anforderung --num-Conn mit jedem Start. Wenn ich stattdessen die Verbindung mit --num-Anruf wiederzuverwenden dann bekomme ich etwa 11 Anfragen pro Sekunde, 1 / 100stel der Geschwindigkeit.

Wenn ich versuche, ab ich eine Auszeit bekommen.

Meine Tests sind

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

und

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

Hier ist ein einfacher reproduzierbarer Server

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 ist ein Multi-Threaded-Server, der schwer zu profilieren ist. Hier ist eine Variante, die Single-Threaded ist:

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

Profilieren, dass mit

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

und schlagen sie mit

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

ich ein Profil erhalten wie

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

Sie sehen, dass fast die ganze Zeit in einem recv ist.

Ich entschied ich für httpref bürgen und schreiben Sie es meine eigene HTTP / 1.1-mit-Keep-Alive-Anfrage und sendet netcat mit:

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

, die ich geschickt mit

nc localhost 8080 < ~/src/send_to_paste.txt

Die Gesamtzeit für 100 Anfragen betrug 0,03 Sekunden, so dass es eine sehr gute Leistung ist.

Dies legt nahe, dass httperf etwas falsch macht (aber es ist ein weit verbreitetes und Stück Code respektiert), also versuchte ich ‚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

instrumentierte den Server übernimmt er eine Anfrage und für die zweite wartet.

Jede Idee, was los ist?

Answer 1

Nach einiger Anstrengung, es scheint entweder Nagle-Algorithmus oder die verzögerte ACK zu sein, oder die Wechselwirkungen zwischen ihnen. Es geht weg, wenn ich so etwas wie

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

Wie habe ich es aufzuspüren? Zuerst habe ich instrumentierte jeden ‚recv‘ in socket.py, so dass ich herausfinden konnte, was recv wartet. Ich würde sehen, etwa 5 des recv von 11 von einer Verzögerung hatte fast 200 ms. Ich konnte nicht herausfinden, warum es eine Verzögerung war. Ich Wireshark dann verwendet, um die Nachrichten zu sehen und bemerkte, dass das war es eigentlich die Sende vom Server an den Client, der die Verzögerung hatte. Das bedeutete, dass etwas in der TCP-Schicht in den ausgehenden Nachrichten von meinen Kunden.

Ein Freund vorgeschlagen, das Offensichtliche, und ich nach „200ms Buchse Verzögerung“ und fand Beschreibungen dieses Problems.

Der Bericht Paste trac ist unter http://trac.pythonpaste.org/pythonpaste/ticket/ 392 zusammen mit einem Patch, der TCP_NODELAY, wenn die Prozedur verwendet HTTP / 1.1.

ermöglicht