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

Вы можете видеть, что почти все время я n a recv.

я решил под залог на httpref и написать мой собственный HTTP/1,1-с-держать-живой запрос и отправить его с помощью 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 -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

После некоторого усилия, это либо Nagle's algorithm, либо задержанный 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.