python BaseHTTPServer 速度緩慢的原因

在用 Bottle 的開發模式時, 發覺有時候速度會異常的慢。等到受不了以後, 按下 ctrl+c 看到以下的 backtrace:

Exception happened during processing of request from ('xxx.xxx.xxx.xxx', 37515)
Traceback (most recent call last):
File "/usr/lib/python2.7/SocketServer.py", line 284, in _handle_request_noblock
self.process_request(request, client_address)
File "/usr/lib/python2.7/SocketServer.py", line 310, in process_request
self.finish_request(request, client_address)
File "/usr/lib/python2.7/SocketServer.py", line 323, in finish_request
self.RequestHandlerClass(request, client_address, self)
File "/usr/lib/python2.7/SocketServer.py", line 638, in __init__
self.handle()
File "/usr/lib/python2.7/wsgiref/simple_server.py", line 121, in handle
self.rfile, self.wfile, self.get_stderr(), self.get_environ()
File "/usr/lib/python2.7/wsgiref/simple_server.py", line 85, in get_environ
host = self.address_string()
File "/usr/lib/python2.7/BaseHTTPServer.py", line 498, in address_string
return socket.getfqdn(host)
File "/usr/lib/python2.7/socket.py", line 137, in getfqdn
hostname, aliases, ipaddrs = gethostbyaddr(name)
KeyboardInterrupt

依照過去的經驗, 這個 gethostbyaddr 相當可疑。

作個簡單測試證實問題:

$ python -c 'import socket; print socket.gethostbyaddr("xxx.xxx.xxx.xxx")'
Traceback (most recent call last):
File "<string>", line 1, in <module>
socket.herror: [Errno 2] Host name lookup failure

再來用老招 ltrace 確認問題源頭:

$ ltrace  python -c 'import socket; print 
socket.gethostbyaddr("xxx.xxx.xxx.xxx")' 2>&1 | grep gethost
( ... 略 ... )
gethostbyaddr_r(0x7fffa5bbb834, 4, 2, 0x7fffa5bb77f0, 0x7fffa5bb7830) = 0

由 man gethostbyaddr 得知它會查 /etc/hosts, 最後在 /etc/hosts 加入一筆 "xxx.xxx.xxx.xxx xxx.xxx.xxx.xxx", 就立即有結果了:

$ python -c 'import socket; print socket.gethostbyaddr("xxx.xxx.xxx.xxx")'
('xxx.xxx.xxx.xxx', [], ['xxx.xxx.xxx.xxx'])

以使用 libsqlite 為例說明如何找到程式的進入點

一直對於如何善用 runtime 資訊找到程式進入點很有興趣, 終於有個不錯的小例子。

目標

假設要觀察的專案有用到 sqlite 儲存資料, 從使用方式知道一開始會先載入 sqlite 的內容, 現在想找到程式讀取第一筆資料的進入點。

第一步先觀察程式如何使用 sqlite, 是用 shared lib 或是直接包含在程式裡:

$ ldd PROG | grep sqlite

Case 1: 沒有結果, 表示 sqlite 的實作直接含在 PROG 裡面

找出和 sqlite 相關的 API:

$ nm PROG | grep sqlite | awk '{print $NF}' | xargs c++filt

或是查官網文件也成, 不過個人覺得 nm + c++filt 這招比較方便也比較酷。

觀察一下後, 得知開檔的 API 有: sqlite3_open, sqlite3_open16, sqlite3_open_v2, 之後用 cgdb 執行程式, 都設中斷點, 就結案了。

Case 2: 有 grep 結果, 表示在 shared lib 裡

若不想看官方文件, 也想來個動態搜集 API, 可用 ltrace:

$ ltrace -l /usr/lib/x86_64-linux-gnu/libsqlite3.so.0 PROG

其中 libsqlite3 的路徑是從 ldd PROG 得知的。

安裝需要的 debug symbol, 以做進一步觀察:

$ aptitude search sqlite | grep dbg # 找到 libsqlite3-0-dbg
$ sudo aptitude install libsqlite3-0-dbg

再來就用 cgdb 執行程式, 準備設中斷點, 結案。

相關參考資料:

• 追踪 glibc 裡的程式
• gdb 如何找到 debug symbol

用 strace 和 ltrace 找出用到的 system call 和 library call

前面提到 host 沒有 call gethostbyaddr, 面惡心善的 Scott 大概是查覺我下載了原始碼, 卻沒有找出確認它的方法。於是在另一篇留言裡說可以用 strace、ltrace 或 gdb 輕易做到這事 (幸好我還沒開始試 profiler 啊...)。

strace 和 ltrace 顧名思議, 它們會列出執行期間用到的 system / library call。若不確定有興趣的函式是那個, 可以用 man page 編號來判別。比方 man gethostbyaddr 顯示被分在  section 3 下, 所以 gethostbyaddr 是 library call [*1]。

分別拿 host 和對照組 getent 試的結果, 可以看到 getent 有打開 /etc/hosts (從 strace 那看到的), 並呼叫 gethostbyaddr；而 host 卻兩者皆無。解開疑惑實乃人生一大痛快之事, 感謝 Scott 的指點。

附上參考用指令：

$ ltrace getent hosts 127.0.0.1 2>&1 | grep gethostby
gethostbyaddr("\177", 4, 2)                      = 0xb7ed0aa0
$ strace getent hosts 127.0.0.1 2>&1 | grep "/etc/hosts"
open("/etc/hosts", O_RDONLY|O_CLOEXEC)  = 3

$ strace host 127.0.0.1 2>&1 | grep "/etc/hosts"
$ ltrace host 127.0.0.1 2>&1 | grep gethostby

另外我好奇之下試了傳說中人人都會寫的 C 版 「Hello, world! 」, 結果發現 compiler 很聰明地用 puts 而非 printf。

參考程式如下：

#include <stdio.h>

int main(void)
{
    printf("hello, world!\n");
    puts("hello, world!\n");
    printf("hello, world! %d\n", 3);
    return 0;
}

執行結果：

$ ltrace ./f > /dev/null
__libc_start_main(0x80483f4, 1, 0xbf812ab4, 0x8048450, 0x8048440 
puts("hello, world!")                            = 14
puts("hello, world!\n")                          = 15
printf("hello, world! %d\n", 3)                  = 16
+++ exited (status 0) +++

接著我用 ltrace 執行 python (ltrace python -c ''), 結果 ltrace 狂噴訊息卻不會停......, 今日閒暇時間用盡這待那天有緣再來研究吧。

2010-02-25 更新

Scott 在留言裡提到也可以用 LD_PRELOAD  抽換動態載入的函式來達到同樣目的 (確認是否有呼叫 gethostbyaddr)。範例程式如下 (稍微修正 Scott 的範例讓它在我的機器能正常 compile)：

$ printf '#include <stdio.h>\n#include <assert.h>\nvoid gethostbyaddr(void) { assert(0); }\n' > t.c
$ gcc -fPIC -shared t.c -o t.so
$ LD_PRELOAD=./t.so getent hosts 127.0.0.1
getent: t.c:3: gethostbyaddr: Assertion `0' failed.
Aborted
$ LD_PRELOAD=./t.so host 127.0.0.1
1.0.0.127.in-addr.arpa domain name pointer localhost.

上面的範例透過 LD_PRELOAD 讓程式改用自訂的 gethostbyaddr。如此一來, 抽換掉懷疑的函式再執行指令, 就知道是否有用到了。LD_PRELOAD 的詳細說明可參考 jserv 翻譯的 《Modifying a Dynamic Library Without Changing the Source Code / 在不更動原始程式碼的前提下，修改動態程式庫》。

備註

1. man man 可看到各 section 的含意, 摘錄如下：
   

   1 Executable programs or shell commands
   2 System calls (functions provided by the kernel)
   3 Library calls (functions within program libraries)
   4 Special files (usually found in /dev)
   5 File formats and conventions eg /etc/passwd
   6 Games
   7 Miscellaneous (including macro packages and conven-
   tions), e.g. man(7), groff(7)
   8 System administration commands (usually only for root)
   9 Kernel routines [Non standard]

   
   總共也才九節, 遊戲竟然自成一節......。

2012-01-30 更新

見 tag strace 下的新文章, 了解比較詳細的 strace 使用例子。