[Python] Debug 一支 daemon 狂吃記憶體的問題… 原來是 lxml 搞的鬼

[Python] Debug 一支 daemon 狂吃記憶體的問題… 原來是 lxml 搞的鬼

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

就是某支 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

(本頁面已被瀏覽過 11 次)

發表迴響

你的電子郵件位址並不會被公開。