曾經遇過的 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。
從上圖中可以觀察到,Xorg 跟 Chrome 的 cputime 在執行到某一個時間點時,就同時出現斜率的變化,跟問題症狀出現的時間也吻合,我這才恍然大悟, 原來禍首是 Chrome。而這關鍵證據,也洗清了 Firefox 的嫌疑。最後是分析出,是 Chrome 有用到 graphic render 加速的功能,關閉後就沒事了。
後來又有一次,大約是 2015/02/20 前後,有更新系統,升級了好些函式庫, Firefox 也從 34版升級到 36版,之後就又產生類似的 Xorg reset 的問題。幸運的是,當時我已經建好有觀測數據的機制,再加上有高手在網路上的討論幫忙,最後將分析範圍縮小至 Xorg intel driver 跟 Firefox 的 render 加速相關的功能。
其中,由上圖這張當時取得的數據圖中,可以看到 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 在系統升級前後的對照:
從上圖中,可以觀察到 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
)"
}