Search by Google

曾經遇過的 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
)"
}
CATALOG
    FEATURED TAGS