python 2.6.6 SimpleHTTPServer耗时的bug

之前因为时间紧迫的缘故，在公司的CentOS 7 机器上部署一个快速实现的数据收集工具，考虑到避免其他语言发布和变更起来麻烦，于是就用 python+bash 实现。

服务端就是最简单不引入任何python包的SimpleHTTPServer+Handler实现的。

偶然一次看日志发现本来应该在三分钟内完成的一个同步/上报循环结果未能如期完成，每个请求看起来相隔十秒左右，最后定位下来是python2.6.6的问题。

简单起见，我用下面重现一下： 10.135.20.45上开了一个进程

python -m SimpleHTTPServer 12888

在另外一台机器上

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
[java@10-135-20-62 ~]$ cat curl-format.txt
time_namelookup: %{time_namelookup}\n
time_connect: %{time_connect}\n
time_appconnect: %{time_appconnect}\n
time_redirect: %{time_redirect}\n
time_pretransfer: %{time_pretransfer}\n
time_starttransfer: %{time_starttransfer}\n
----------time_total: %{time_total}\n
[java@10-135-20-62 ~]$ curl -w "@curl-format.txt" -o /dev/null -s -L "10.135.20.45:12888"
time_namelookup: 0.000
time_connect: 0.000
time_appconnect: 0.000
time_redirect: 0.000
time_pretransfer: 0.000
time_starttransfer: 10.013
----------time_total: 10.013

这里两个问题：
1）一个简单的GET请求耗时10秒，10秒看起来像是服务器设置的超时时间。
2）而且10秒都花费在 starttransfer

如何定位问题？显然逐步打点耗时是可以的，但是如果用搜索引擎更快，我在python社区上找到一个提问，作者遇到同样现象，但是pytohn2.7以后就没有问题。

有个回答说是 pytohn解析header时候\r\n的问题，也有说是socket未close问题，我看了下代码，不像。

不过这个提问给了我思路，于是我比较了python 2.6/2.7各自的SimpleHTTPServer.py文件。
考虑到linux版本众多且你可能也记不住，友情提示一个定位该文件的方法：

1
2
3
4
[java@10-135-20-62 ~]$ python --version
Python 2.6.6
[java@10-135-20-62 ~]$ python -c 'import sys; print sys.path'
['', '/usr/lib64/python26.zip', '/usr/lib64/python2.6', '/usr/lib64/python2.6/plat-linux2', '/usr/lib64/python2.6/lib-tk', '/usr/lib64/python2.6/lib-old', '/usr/lib64/python2.6/lib-dynload', '/usr/lib64/python2.6/site-packages', '/usr/lib64/python2.6/site-packages/gtk-2.0', '/usr/lib/python2.6/site-packages', '/usr/lib/python2.6/site-packages/setuptools-0.6c11-py2.6.egg-info']

一般就在 /usr/lib64/python2.6/ 下面了。
不过2.6/2.7的SimpleHTTPServer.py没有明显差异，继续再比对他们的父类：BaseHTTPServer.py
下图简单列下不同点。

时间问题，直接上答案，问题就出在log_message里，python原意只是记录response的相关结果，但没想到会成为耗时的元凶：

1
2
3
4
5
6
7
def address_string(self):
    """Return the client address formatted for logging.
    This version looks up the full hostname using gethostbyaddr(),
    and tries to find a name that contains at least one dot.
    """
    host, port = self.client_address[:2]
    return socket.getfqdn(host)

我在该机器上跑一下，发现却是是耗费10秒

time python -c 'import socket; print socket.getfqdn()'

python 2.7 之后就改过来了，不再适用 address_string，所以在现代服务器上不会出现上述问题。

getfqdn为什么会耗时呢？这和pyhon hostname 解析实现相关，后续可分享一下。

以上简单记录遇到的问题，读者可留意。解决方法其实可以替换python的BaseHTTPServer.py，也可以自己拷贝出来一份修改，但说到底不如正规的方案去实现。

后记：

getfqdn 底层调用的就是 socket.gethostbyaddr() – map an IP number or hostname to DNS info
(生产环境配置 域名/反向域名解析服务)

1
2
3
4
5
6
7
8
9
10
11
12
13
14
[java@10-135-20-62 ~]$ time python -c 'import socket; print socket.gethostbyaddr("10.135.20.62")'
('localhost', ['localhost.localdomain', 'localhost4', 'localhost4.localdomain4'], ['10.135.20.62'])

real    0m0.019s
user    0m0.014s
sys 0m0.004s
[java@10-135-20-62 ~]$ time python -c 'import socket; print socket.gethostbyaddr("10.135.20.39")'
Traceback (most recent call last):
  File "<string>", line 1, in <module>
socket.herror: [Errno 2] Host name lookup failure

real    0m10.033s
user    0m0.018s
sys 0m0.004s

另 socket.py

1
2
3
4
5
[java@10-135-20-62 ~]$ python -c 'import _socket;print(_socket.__file__)'
/usr/lib64/python2.6/lib-dynload/_socketmodule.so
[java@10-135-20-62 ~]$ nm -D /usr/lib64/python2.6/lib-dynload/_socketmodule.so
[java@10-135-20-62 ~]$ objdump -tT /usr/lib64/python2.6/lib-dynload/_socketmodule.so
...