最近專案的程式，被其他部門的同事測出一個奇怪的問題，

就是某支 python daemon 平常沒事，

但在隨機的狀態下，會突然狂吃記憶體…

這個問題用同樣的測試資料去打，不一定會出現，

但在某些機器上跑個幾天的話，出現的機會還不小…

 

雖然沒有確切的方法可以重現問題，

但既然某些機器跑久了就會出現，

就想等問題出現時，再用 gdb 去看看 daemon 在幹嘛～

結果每次問題出現時，因為記憶體吃太多，

Linux 的 OOM (out-of-memory) killer 就跑出來把 daemon 殺掉了，

毀屍滅跡，什麼都看不到…

 

沒辦法，只好先寫個小程式，

當 daemon 的 VmSize 超過 10GB 時 (平常不到 3GB)，

就下一個 SIGSTOP 的信號，把 daemon 停掉，

這樣子記憶體不會再長，就不會再被 OOM killer 幹掉了：

#!/bin/sh

STOPPED_PID=""
MAX_VMSIZE="10000000000"

while true
do
    # Get daemon pid
    PID=$(ps aux | egrep "python.*testdaemon" | egrep -v "grep|/bin/sh" | awk '{print $2}')
    if [ "${PID}" != "" ]; then
        
        # Get vm size
        VMSIZE=$(awk '{print $23}' /proc/${PID}/stat)

        if [ "${VMSIZE}" -lt "${MAX_VMSIZE}" ]; then
            echo "$(date): VM size of pid ${PID} is ${VMSIZE}."

        elif [ "${PID}" != "${STOPPED_PID}" ]; then
            echo "$(date): VM size of pid ${PID} is ${VMSIZE}, larger than ${MAX_VMSIZE}, stop it!"
            kill -STOP "${PID}"
            STOPPED_PID="${PID}"
        fi
    fi

    sleep 5
done

 

跑了這個小程式之後，果真抓到 daemon 記憶體狂長的狀況，

daemon 也順利的被 SIGSTOP 停了下來～

這時候就可以用 gdb 進去看看啦～

 

用 gdb -p <pid> 開始 debug，

先用 info thread 看一下，發現有許多 thread 停留在相同的位置，

進去其中一根 thread (用 thread <thread id>) 再下 bt 看看：

(gdb) bt

#0  0x00007f8a4c7bd79b in do_futex_wait.constprop.1 () from /lib64/libpthread.so.0

#1  0x00007f8a4c7bd82f in __new_sem_wait_slow.constprop.0 () from /lib64/libpthread.so.0

#2  0x00007f8a4c7bd8cb in sem_wait@@GLIBC_2.2.5 () from /lib64/libpthread.so.0

#3  0x00007f8a4cadd535 in PyThread_acquire_lock (lock=0x7f8a182a84c0, waitflag=1) at /usr/src/debug/Python-2.7.5/Python/thread_pthread.h:323

#4  0x00007f8a4023bc78 in __pyx_f_4lxml_5etree_14_ParserContext_prepare () from /usr/lib64/python2.7/site-packages/lxml/etree.so

#5  0x00007f8a40208075 in __pyx_f_4lxml_5etree_11_BaseParser__parseDoc () from /usr/lib64/python2.7/site-packages/lxml/etree.so

#6  0x00007f8a401fc49f in __pyx_f_4lxml_5etree__parseDoc () from /usr/lib64/python2.7/site-packages/lxml/etree.so

#7  0x00007f8a401fc679 in __pyx_f_4lxml_5etree__parseMemoryDocument () from /usr/lib64/python2.7/site-packages/lxml/etree.so

#8  0x00007f8a4025106d in __pyx_pw_4lxml_5etree_23fromstring () from /usr/lib64/python2.7/site-packages/lxml/etree.so

#9  0x00007f8a4cab100a in ext_do_call (nk=, na=, flags=, pp_stack=0x7f8a16ffb2f8, func=)
    at /usr/src/debug/Python-2.7.5/Python/ceval.c:4718

#10 PyEval_EvalFrameEx (
f=f@entry=Frame 0x7f8a0c9a4eb0, for file /usr/lib64/python2.7/site-packages/lxml/html/__init__.py, line 568, in document_fromstring (html='\n<!--\n\n This is a HTML file...(truncated), throwflag=throwflag@entry=0) at /usr/src/debug/Python-2.7.5/Python/ceval.c:3079

 

先解釋一下，這支 daemon 裡有許多 thread 會去下載網頁，

接著用 lxml 的 fromstring() 函式來解析這些網頁裡面的資料。

看起來 fromstring() 會呼叫到 document_fromstring()，

再接著一連串的呼叫之後，就卡在一個 semaphore 之類的 lock 上面了…

 

如果一根 thread 剛好出現上面的 call stack，

還可以理解成在等 lock 時，剛好 daemon 被 SIGSTOP 信號給停了下來。

但有一堆 thread 都在等 lock？這看起來就有一點奇怪了…

懷疑是不是 lxml 裡面有什麼 race condition，

在 multi-thread 時不小心撞進去的話，可能就踩進那個 lock，

也許在拿不到 lock 的狀況下，lxml 會再去取用記憶體再試一次，

在持續取不到 lock 的情況下，可能就造成記憶體狂吃的狀態…

 

↑ 上面是一種假設，要驗證這個假設的話，

可以試試用許多 thread 跑 lxml 的 fromstring()，

看看能不能加速問題的產生 (假設這個推論無誤的話)～

 

下面這就是測試 lxml 的 python 程式，

基本上就是用非常多的 thread，持續不停的去跑 lxml 的 fromstring()，

如果程式突然不動了，就是重現問題了：

#!/usr/bin/env python

import threading


def parse_html(path):
    with open(path, "r") as f:
        return XH.fromstring(f.read())


def thread_func(i):
    while True:
        print "Thread %03d" % (i), parse_html("problem.html")


if __name__ == "__main__":
    t_list = []
    for i in xrange(100):
        t = threading.Thread(target=thread_func, args=(i,))
        t_list.append(t)

    for t in t_list:
        t.start()

    for t in t_list:
        t.join()

 

我本來是從 gdb 列出的 call stack 裡，找出卡住的 thread 最後在處理的網頁檔，

然後把這些網頁檔全都塞給 fromstring()，

但後來發現某個特定的 problem.html 就能觸發問題，所以最後只留下它～

 

跑了這個小程式之後，大約十幾秒內，程式就會卡住，

重覆執行了幾次都是，算是可以穩定的重現問題。

這下子應該可以確認是 lxml 的問題了，但要怎麼解決呢？

 

要從 lxml 的原始碼找出問題，實在太花時間…

(老實說我也看不太懂 lxml 的原始碼… Orz)

我們用的 lxml 是 3.2.1 版，那就先試試最新版的 4.1.1 會不會有問題吧～

為了怕換 lxml 影響現有系統，我是先安裝了 virtualenvwrapper，

再用如下的指令安裝 lxml 4.1.1 版本：

pip install lxml==4.1.1

 

賓果！4.1.1 不會出現卡住的問題！

這真是太振奮人心了，這樣至少知道只要將 lxml 升級到最新版，就能解決這問題～

不過依工程師精神，還是要找一下哪一版修好的…

用二分搜尋法把 lxml 3.2.1 到 4.1.1 中間的版本都試一下，

發現 3.8.0 還有問題，但接下來的 4.0.0 版就沒事了～

這樣子就可以去比對 3.8.0 和 4.0.0 到底改了什麼東西，

可能會造成 fromstring() 的行為改變囉～

 

參考資料：Tracking Down a Freaky Python Memory Leak