曾經遇過的 Firefox 與 Chrome 的不穩定問題

Posted by 每特17劃 on 2017-06-04

曾經遇過的 Firefox 與 Chrome 的不穩定問題

記得很久之前,(註:2014-09-02),有個問題一直很困擾我。就是我的筆電,只要開機一段時間,就會在某個時間點就會突然產生 CPU 飆高,風扇一直狂轉的狀況。即使把所有應用程式關閉,仍沒辦法穩定下來,直到我重啟 Xorg 視窗系統,才會恢復正常。這個問題,常常無預警的中斷我的電腦操作,搞得我很痛苦。

我試圖找出問題的根源在那裡,大致將可能的嫌疑犯縮小到 Xorg,Firefox,Chrome,qtile(Window Manager) 這4個主程式。不過,一直沒辦法精確的 reproduce 問題的發生。當時,正值 Firefox 跟 Chrome 在競爭效能之際,我看 top 的資料,都是 Firefox 用的資源比 Chrome 還多,所以有好一段時間,以為罪魁禍首是 Firefox 。

後來,我開始接觸並上手 ganglia/graphite 這類監測工具,有天我想到,之前都是在監看遠端主機的數據,我何不運用這工具直接觀測我自己每天在用的NB呢?! 於是我開始撰寫幾個抓 cputime/memory 的script 跟設定,我直到我後來取得下面這張關鍵數據圖之後,我才明白,原來我的筆電上的問題源頭是 Chrome。

Imgur

從上圖中可以觀察到,Xorg 跟 Chrome 的 cputime 在執行到某一個時間點時,就同時出現斜率的變化,跟問題症狀出現的時間也吻合,我這才恍然大悟, 原來禍首是 Chrome。而這關鍵證據,也洗清了 Firefox 的嫌疑。最後是分析出,是 Chrome 有用到 graphic render 加速的功能,關閉後就沒事了。

後來又有一次,大約是 2015/02/20 前後,有更新系統,升級了好些函式庫, Firefox 也從 34版升級到 36版,之後就又產生類似的 Xorg reset 的問題。幸運的是,當時我已經建好有觀測數據的機制,再加上有高手在網路上的討論幫忙,最後將分析範圍縮小至 Xorg intel driver 跟 Firefox 的 render 加速相關的功能。

Imgur

其中,由上圖這張當時取得的數據圖中,可以看到 Xorg 的 vesa/intel 驅動程式的不同,及 accel 的 on/off 的一些變化。由此可證實是 Xorg accel 跟其相關的下游應用程式的部份所致。雖然,最終沒能找出是那一段程式導致 mem leak ,但透過更換 driver 並關閉 accel 的選項,暫時避免掉嚴重的 reset 危機。

(註: 後來 Firefox 在某一版本更新後,該問題就消失了)

這兩次經驗(還有先前的一些小案例),給我非常非常大的啟發。 以往程式 debug 經驗,多數都依賴 gdb, xdebug, … 或是跑 unit test 來測試程式的問題,這些通常重複操作就能重現一樣的問題。但對於這類正常執行運作一段時間,然後突然崩潰的問題,常常是束手無策。因為,問題發生的那瞬間,我們往往不在現場,也沒有任何除錯紀錄。沒想到,僅僅透過簡單的 cputime/memory 這2道的數據偵測歷史紀錄,對問題的原因分析的幫助會這麼大。

這也讓我意識到,將飛行安全提升到更高等級的關鍵,或許不是風洞測試,而是黑盒子(Flight Recorder)。想想看,一台穩定飛行20年的飛機,出事的時候就只有那瞬間,我們只有一次機會可以補捉相關線索。我想,在時光機發明出來之前,只有透過 Logger 機制,才能迎戰這類 runtime 執行期的問題。這也讓我開始有了 Logger Driven Design 這個想法思考。

最後,再提供一張當時截圖到的 Xorg 在系統升級前後的對照:

Imgur

從上圖中,可以觀察到 Xorg 在系統更新前的舊版本,其使用的 mem 都不到 200MB , 而且運作 2~3 個星期以上,都沒有任何 mem 用量累積。 zero memory leak 水準的軟體確實存在,是真的可以達成的,而且就在我每天都在使用的軟體之中。或許,更高水準的軟體方法,不見得在最新的技術潮流,而是隱身在這些老牌軟體專案的某個角落,等待著我們再重新去發掘它。

註1:

FB 上的留言討論:

https://www.facebook.com/groups/hackingday/permalink/903494983005834/

註2:

我所使用的觀測工具是 shell script + collectd + graphite/influxdb, 我寫的 scripts 大致如下:

cputime:

#!/usr/bin/env bash

source "$(readlink -f $(dirname $0))/common.inc"

HOSTNAME="${COLLECTD_HOSTNAME:-localhost}"
INTERVAL="${COLLECTD_INTERVAL:-60}"

OUTPUT=`get_cpu_time_output`
CNT=`echo "$OUTPUT"| wc -l`
for (( i=1 ; i <= $CNT ; i++ ))
do
      key=`echo "$OUTPUT" | tail -n +${i} | head -1 | awk '{print $1}'`
    VALUE=`echo "$OUTPUT" | tail -n +${i} | head -1 | awk '{print $2}'`
    echo "PUTVAL \"$HOSTNAME/me/gauge-cputime.$key\" interval=$INTERVAL N:$VALUE" 
done

xorg:

#!/usr/bin/env bash

source "$(readlink -f $(dirname $0))/common.inc"

HOSTNAME="${COLLECTD_HOSTNAME:-localhost}"
INTERVAL="${COLLECTD_INTERVAL:-60}"

NAME="xorg"
PROC_PATTERN="X -nolisten"


qpid=$( get_proc_pid "$PROC_PATTERN" )

echo "PUTVAL \"$HOSTNAME/me/gauge-${NAME}_rss\" interval=$INTERVAL N:$( get_ps_output $qpid | get_rss )" 
echo "PUTVAL \"$HOSTNAME/me/gauge-${NAME}_vsz\" interval=$INTERVAL N:$( get_ps_output $qpid | get_vsz )" 
echo "PUTVAL \"$HOSTNAME/me/gauge-${NAME}_cputime\" interval=$INTERVAL N:$( get_ps_output $qpid | get_cputime )" 

firefox:

#!/usr/bin/env bash

source "$(readlink -f $(dirname $0))/common.inc"

HOSTNAME="${COLLECTD_HOSTNAME:-localhost}"
INTERVAL="${COLLECTD_INTERVAL:-60}"

NAME="firefox"
PROC_PATTERN="opt.*firefox"


qpid=$( get_proc_pid "$PROC_PATTERN" )
if [ -n "$qpid" ]; then
  echo "PUTVAL \"$HOSTNAME/me/gauge-${NAME}_pss\" interval=$INTERVAL N:$( get_pss_by_proc_grp "${PROC_PATTERN}" )" 
  echo "PUTVAL \"$HOSTNAME/me/gauge-${NAME}_rss\" interval=$INTERVAL N:$( get_ps_output $qpid | get_rss )" 
  echo "PUTVAL \"$HOSTNAME/me/gauge-${NAME}_vsz\" interval=$INTERVAL N:$( get_ps_output $qpid | get_vsz )" 
  echo "PUTVAL \"$HOSTNAME/me/gauge-${NAME}_cputime\" interval=$INTERVAL N:$( get_ps_output $qpid | get_cputime )" 
fi

chrome:

#!/usr/bin/env bash

source "$(readlink -f $(dirname $0))/common.inc"

HOSTNAME="${COLLECTD_HOSTNAME:-localhost}"
INTERVAL="${COLLECTD_INTERVAL:-60}"

NAME="chrome"
PROC_PATTERN="opt.*chrome"


qpid=$( get_proc_pid "$PROC_PATTERN" )

if [ -n "$qpid" ]; then
  echo "PUTVAL \"$HOSTNAME/me/gauge-${NAME}_pss\" interval=$INTERVAL N:$( get_pss_by_proc_grp "${PROC_PATTERN}" )" 
  echo "PUTVAL \"$HOSTNAME/me/gauge-${NAME}_rss\" interval=$INTERVAL N:$( get_ps_output $qpid | get_rss )" 
  echo "PUTVAL \"$HOSTNAME/me/gauge-${NAME}_vsz\" interval=$INTERVAL N:$( get_ps_output $qpid | get_vsz )" 
  echo "PUTVAL \"$HOSTNAME/me/gauge-${NAME}_cputime\" interval=$INTERVAL N:$( get_ps_output $qpid | get_cputime )" 
fi

common.inc:

#!/usr/bin/env bash

function get_proc_pid(){
    local proc_pattern="$1"
    ps aux --forest | grep -e "${proc_pattern}" | grep -v 'grep' | head -1 | awk '{print $2}'
}

function get_ps_output(){
    local proc_id="$1"

    ps --no-header -o rss,vsz,cputime,etimes,nlwp $proc_id
}

function get_cpu_time_output(){
    cat /proc/stat | grep -e '^cpu' | awk '{ print $1, ($2+$4)/100.0 }'
}

function do_sum(){
        awk '{sum += $1} END {print sum}'
}

function get_pss_by_pid(){
    while read proc_id; do
        sudo cat /proc/$proc_id/smaps | grep Pss | awk '{print $2 * 1024 }' | do_sum
    done
}

function get_pss_by_proc_grp(){
	local proc_patt="$1"

	ps aux --forest | grep -A 9999 "${proc_patt}" | parse_child | get_pss_by_pid | do_sum
}

function get_rss() {
    awk "{print \$1 * 1024 }"
}

function get_vsz() {
    awk "{print \$2 * 1024 }"
}

function time2int() {

python -c "$(cat <<EOPY
import sys
res = 0
for line in sys.stdin:
        ary = line.strip().split(':')
        ary.reverse()
        if len(ary) > 0:
          res = res + int(ary[0])
        if len(ary) > 1:
          res = res + int(ary[1]) * 60
        if len(ary) > 2:
          res = res + int(ary[2]) * 60 * 60
        if len(ary) > 3:
          res = res + int(ary[3]) * 60 * 60 * 24
        print( res )
EOPY
)"

}


function get_cputime() {
    awk "{print \$3}" |  time2int
}

function parse_child(){
python -c "$(cat <<EOPY
import sys
beg = False
end = False
for line in sys.stdin:
        ary = line.split()
        cmd = ary[10].strip()
        pid = ary[1].strip()
        if cmd != "\_" and cmd != "|":
            if beg == False:
                beg = True
            else:
                if end == False:
                    end = True
                    break

        print ( "%s" % ( pid ) )
EOPY
)"
}