вставить.httpserver и замедлить работу с помощью HTTP/1.1 Keep-alive;протестировано с помощью httperf и ab

Question

У меня есть веб-сервер, основанный на paste.httpserver в качестве адаптера между HTTP и WSGI.Когда я выполняю измерения производительности с помощью httperf, я могу выполнять более 1000 запросов в секунду, если каждый раз запускаю новый запрос, используя --num-conn.Если я вместо этого повторно использую соединение, используя --num-call, то я получаю около 11 запросов в секунду, что составляет 1/100-ю от скорости.

Если я попробую ab, я получу тайм-аут.

Мои тесты таковы

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

и

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

Вот простой воспроизводимый сервер

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

Это многопоточный сервер, который трудно профилировать.Вот вариант, который является однопоточным:

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

Профилирование этого с помощью

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

и ударяя по нему с

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

Я получаю профиль, подобный

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

Вы можете видеть, что почти все время находится в recv.

Я решил отказаться от httpref и написать свой собственный HTTP/1.1-with-keep-alive запрос и отправить его с помощью 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

который я отправил с

nc localhost 8080 < ~/src/send_to_paste.txt

Общее время обработки 100 запросов составило 0,03 секунды, так что это очень хорошая производительность.

Это говорит о том, что httperf делает что-то неправильно (но это широко используемый и уважаемый фрагмент кода), поэтому я попробовал '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

Настраивая сервер, он обрабатывает один запрос и ожидает второго.

Есть какие-нибудь идеи о том, что происходит?

Answer 1

После некоторых усилий, похоже, это либо Алгоритм Нэгла или отложенный ACK, или взаимодействия между ними.Это исчезнет, если я сделаю что-то вроде

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

Как мне удалось его выследить?Во-первых, я инструментировал каждый 'recv' в socket.py, чтобы я мог выяснить, какой recv ожидал.Я бы увидел, что примерно у 5 recv из 11 задержка составляла почти 200 мс.Я не мог понять, почему произошла какая-то задержка.Затем я использовал Wireshark для просмотра сообщений и заметил, что на самом деле это была отправка с сервера клиенту, которая имела задержку.Это что-то значило на уровне TCP в исходящих сообщениях от моего клиента.

Друг предложил очевидное, и я поискал "задержку сокета на 200 мс" и нашел описания этой проблемы.

Отчет о прохождении вставки находится по адресу http://trac.pythonpaste.org/pythonpaste/ticket/392 вместе с исправлением, которое включает TCP_NODELAY, когда обработчик использует HTTP / 1.1.