paste.httpserver与HTTP/1.1 Keep-alive的慢速问题;用httperf和ab测试过
我有一个基于paste.httpserver的网络服务器,它充当HTTP和WSGI之间的适配器。当我用httperf进行性能测试时,如果每次都新建一个请求(使用--num-conn),我可以达到每秒超过1000个请求的速度。但如果我使用--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}
....
你可以看到几乎所有的时间都花在了接收数据上。
我决定放弃httperf,自己写一个支持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'工具
% 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
在对服务器进行监控时,它处理了一个请求,然后在等待第二个请求。
你知道发生了什么事吗?
1 个回答
经过一番努力,我发现问题可能是因为Nagle算法或者延迟确认,或者它们之间的相互作用。如果我做一些特定的操作,这个问题就会消失。
server.socket.setsockopt(socket.IPPROTO_TCP, socket.TCP_NODELAY, 1)
我怎么找到这个问题的呢?首先,我在socket.py的每个'recv'函数里加了监控,这样我就能知道哪个'recv'在等待。我发现11个'recv'中大约有5个的延迟接近200毫秒。我搞不清楚为什么会有延迟。然后我用Wireshark这个工具来观察消息,发现其实是服务器发送给客户端的消息出现了延迟。这意味着在我客户端发出的消息的TCP层面上出了问题。
一个朋友给了我一个明显的建议,我搜索了“200毫秒 socket 延迟”,找到了关于这个问题的描述。
关于这个问题的详细报告可以在http://trac.pythonpaste.org/pythonpaste/ticket/392找到,里面还有一个补丁,可以在处理器使用HTTP/1.1时启用TCP_NODELAY。