解決問題，別擴充套件問題
由來
最近有個需求需要統計一個方法的耗時，這個方法前後各打出一條日誌，類似於 [INFO] 20180913 19:24:01.442 method start/end unique_id ，unique_id 是我們框架為了區分每一個請求而生成的唯一ID。
由於在高併發場景下， start 和 end 的日誌並不一定是挨著的，很可能方法執行期間，又有其他的日誌輸出了出來，於是產生了這樣的日誌：
[INFO] 20180913 19:24:01.442 method start aaa [INFO] 20180913 19:24:01.452 method start bbb [INFO] 20180913 19:24:01.456 do something ccc [INFO] 20180913 19:24:01.562 method end aaa ...
由於日誌在伺服器上，不想再把日誌 down 下來，又因為日誌比較規範，於是決定自己寫個 shell 指令碼來處理這些資料。花了一下午時間，換了 4 個 shell 指令碼，才優雅地處理了這些資料，其中走進了思維誤區，踩了一個擴充套件問題的大坑。
轉載隨意，請註明來源地址：https://zhenbianshu.github.io
初入坑
思路
處理這個問題的第一步，肯定是拿到要處理的這些資料，首先用 grep 命令加輸出重定向可以輕鬆地拿到這些資料，一共 76W。
由於需要考慮不同請求日誌的穿插問題，又加上用久了 PHP 的陣列和 Java 的 map 而形成的慣性思維，又加上我最近學習的 bash 的關聯資料用法，我決定把 start 日誌和 end 日誌，拆分為兩個檔案，然後將這些資料生成兩個大的關聯陣列，以 unique_id 為鍵，以當時的時間戳為值，分別儲存請求的開始時間(arr_start)和結束時間(arr_end)。最後再遍歷結束時間陣列(arr_end)，並查詢開始時間陣列內的值，進行減法運算，將差值輸出到另一個檔案裡。
這樣，寫出的指令碼就是這樣：
指令碼
#!/bin/bash
# 獲取準確時間的函式
function get_acc_time() {
arr=($1)
date_str=${arr[1]}" "${arr[2]}
# date -d "date_str" "+%format" 可以指定輸入日期，以替代預設的當前時間
# cut 根據 '.' 切分，並取第二個欄位
echo `date -d "$date_str" "+%s"`"."`echo${arr[2]} | cut -d '.' -f2`
}
# 使用 -A 宣告關聯陣列
declare -A arr_start
declare -A arr_end
# 構造開始時間陣列
while read -r start_line
do
arr_start[${arr[5]}]=`get_acc_time $start_line`
done < $start_file
# 構造結束時間陣列
while read -r end_line
do
arr_end[${arr[5]}]=`get_acc_time $end_line`
done < $end_file
# 遍歷結束時間陣列
for request in ${!arr_end[*]}
do
end_time=${arr_end[$request]}
start_time=${arr_start[$request]}
if [ -z "$start_time" ]; then
continue;
fi
# 直接使用 bc 不會顯示小數點前的 0
echo `print "%.3f" echo "scale=3;$end_time-$start_time"| bc` >> $out_file
done
越陷越深
這個指令碼有個缺陷就是它執行得非常慢（後面小節有對它速度的分析），而且中途沒有輸出，我根本不知道它什麼進度，運行了半個小時還沒有輸出，急於解決問題，我就換了一個方法。
排序並行法
這時我想讓它忙儘快有結果輸出出來，讓我隨時能看到進度，而且只有部分結果出來時我也能進行分析。那麼有沒有辦法讓我在遍歷”結束日誌”的時候能很輕鬆地找到”開始日誌”裡面對應的那條請求日誌呢？
因為日誌是按時間排序的，如果保持其時間序的話，我每次查詢開始日誌都得在一定的時間範圍內找，而且遍歷到下一條結束日誌後，開始日誌的查詢起點也不好確定。 如果用上面的日誌示例，我查詢 unique_id 為 aaa 的請求時，我必須查詢 19:24:01.442-19:24:01.562 這一時間範圍內的所有日誌，而且查詢 unique_id 為 bbb 的請求時，無法確定時間起點，如果從開頭遍歷的話，消耗會非常大。
這個方法肯定是不可行的，但我可以把這些請求以 unique_id 排序，排序後它們會像兩條並行的線，就像：
開始日誌 aaa bbb ccc ddd eee fff 結束日誌 aaa bbb ccc ddd eee fff
我只需要記錄每一個 unique_id 在結束日誌裡的的行數，查詢開始時間時，直接取開始日誌裡的對應行就可以了。
使用 sort -k 5 start.log >> start_sorted.log 將日誌排下序，再寫指令碼處理。
#!/bin/bash
function get_acc_time() {
date_str=$1" "$2
acc_time=`date -d "$date_str" "+%s"`"."`echo$2 | cut -d '.' -f2`
echo $acc_time
}
total=`cat $end_file | wc -l`
i=0
while read -r start_line
do
i=`expr $i + 1`
arr_start=($start_line)
# 如果取不到的話去下一行取
for j in `seq $i $total`
do
end_line=`awk "NR==$j" $end_file` // 用 awk 直接取到第 N 行的資料
arr_end=($end_line)
# 判斷兩條日誌的 unique_id 一樣
if [ "${arr_start[5]}" = "${arr_end[5]}" ];then
break
fi
i=`expr $i + 1`
done
start_time=`get_acc_time ${arr_start[1]} ${arr_start[2]}`
end_time=`get_acc_time ${arr_end[1]} ${arr_end[2]}`
echo `print "%.3f" echo "scale=3;$end_time-$start_time"| bc` >> $out_file
done < $start_file
非常遺憾的是，這個指令碼執行得非常慢，以每秒 1 個結果的速度輸出，不過我還沒有技窮，於是想新的辦法來解決。
全量載入法
這次我以為是 awk 執行得很慢，於是我想使用新的策略來替代 awk，這時我想到將日誌全量載入到記憶體中處理。 於是我又寫出了新的指令碼：
#!/bin/bash
function get_time() {
date_str=$1" "`echo $2 | cut -d '.' -f1`
acc_time=`date -d "$date_str" "+%s"`"."`echo$2 | cut -d '.' -f2`
echo $acc_time
}
SAVEIFS=$IFS # 儲存系統原來的分隔符（空格）
IFS=$'\n' # 將分隔符設定為換行，這樣才能將檔案按行分隔為陣列
start_lines=(`cat $start_file`)
end_lines=(`cat $end_file`)
total=`cat $end_file | wc -l`
i=0
IFS=$SAVEIFS # 將分隔符還設定回空格，後續使用它將每行日誌切分為陣列
for start_line in ${start_lines[*]}
do
arr_start=($start_line)
for j in `seq $i $total`
do
end_line=${end_lines[$j]}
arr_end=($end_line)
if [-z "$end_line"-o "${arr_start[5]}" = "${arr_end[5]}" ];then
break
fi
i=`expr $i + 1`
done
i=`expr $i + 1`
start_time=`get_time ${arr_start[1]} ${arr_start[2]}`
end_time=`get_time ${arr_end[1]} ${arr_end[2]}`
echo `print "%.3f" echo "scale=3;$end_time-$start_time"| bc` >> $out_file
done
指令碼執行起來後，由於需要一次載入整個日誌檔案，再生成大陣列，系統頓時嚴重卡頓(幸好早把日誌傳到了測試機上)，一陣卡頓過後，我看著依然每秒 1 個的輸出沉默了。
新的思路
這時終於想到問一下邊上的同事，跟同事講了一下需求，又說了我怎麼做的之後，同事的第一反應是 “你為啥非要把日誌拆開？”，頓時豁然開朗了，原來我一開始就錯了。
如果不把日誌分開，而是存在同一個檔案的話，根據 unique_id 排序的話，兩個請求的日誌一定是在一起的。再用 paste 命令稍做處理，將相鄰的兩條日誌合併成一行，再使用迴圈讀就行了，命令很簡單： cat start.log end.log | sort -k 5 | paste - - cost.log ，檔案生成後，再寫指令碼來處理。
#!/bin/bash
function get_time() {
date_str=$1" "`echo $2 | cut -d '.' -f1`
acc_time=`date -d "$date_str" "+%s"`"."`echo$2 | cut -d '.' -f2`
echo $acc_time
}
while read -r start_line
do
arr_s=($start_line)
start_time=`get_time ${arr_s[1]} ${arr_s[2]}`
end_time=`get_time ${arr_s[5]} ${arr_s[6]}`
# 每行前面輸出一個 unique_id
echo -e ${arr_s[5]}" \c" >> $out_file
echo `print "%.3f" echo "scale=3;$end_time-$start_time"| bc` >> $out_file
done < $start_file
再次執行，發現速度雖然還不盡如人意，但每秒至少能有幾十個輸出了。使用 split 將檔案拆分為多個，開啟多個程序同時處理，半個多小時，終於將結果統計出來了。
指令碼執行速度分析
問題雖然解決了，但指令碼執行慢的原因卻不可放過，於是今天用 strace 命令分析了一下。 由於 strace 的 -c 選項只統計系統呼叫的時間，而系統呼叫實際上是非常快的，我更需要的時檢視的是各個系統呼叫之間的時間，於是我使用 -r 選項輸出了兩個步驟之間的相對時間，統計了各步驟間相對時間耗時。
read 慢
從統計資料可以看到它的很大一部分時間都消耗在 read 步驟上，那麼, read 為什麼會這麼慢呢？
仔細檢視程式碼發現我使用很多 ` 建立子程序，於是使用 stace 的 -f 選項跟蹤子程序，看到輸出如下： 
可以看出程序建立一個子程序並執行命令，到最後回收子程序的消耗是很大的，需要對子程序進行訊號處理，檔案描述符等操作。最終工作的程式碼只有一個 write 且耗時很短。
由於指令碼是完全同步執行的，所以子程序耗時很長，主程序的 read 也只能等待，導致整個指令碼的耗時增加。
為了驗證我的猜測，我把指令碼簡寫後，使用 time 命令統計了耗時分佈。
while read -r start_line do str=`echo "hello"` done < $start_file
可以看得出來，絕大部分時間都是系統時間。
迴圈慢
另外一個問題是，最終解決問題的指令碼和全量載入法的指令碼在主要步驟上並沒有太大差異，但效率為什麼會差這麼多呢？
我忽然注意到腳本里的一個迴圈 for j in `seq $i $total` ， 這個語句也建立了子程序，那它跟主程序之間的互動就是問題了所在了， 在指令碼執行初期， $i 非常小，而 $total 是結束日誌的總行數：76W，如果 seq 命令是產生一個這麼大的陣列。。。
我使用 strace 跟蹤了這個指令碼，發現有大量的此類系統呼叫： 
總算破案了。
小結
在這個問題的解決上，我的做法有很多不對的地方。
首先，解決問題過程中，指令碼不正常地效率低，我沒有仔細分析，而是在不停地避開問題，尋找新的解決方案，但新方案的實施也總有困難，結果總在不停地試錯路上。
然後是解決問題有些一根筋了，看似找到了一個又一個方案，其實這些方案都是舊方案的補丁，而沒有真正地解決問題。從A問題引入了B問題，然後為了解決B問題又引入了C問題，直到撞到南牆。
在第一家公司，初入程式設計領域時，我當時的 leader 老是跟我們強調一定要避免 “X-Y” 問題。針對 X 問題提出了一個方案，在方案實施過程中，遇到了問題 Y，於是不停地查詢 Y 問題的解決辦法，而忽略了原來的問題 X。有時候，方案可能是完全錯誤的，解決 Y 問題可能完全沒有意義，換一種方案，原來的問題就全解決了。
在跟別人交流問題時，我一直把初始需求說清楚，避免此類問題，沒想到這次不知不覺就沉入其中了，下次一定注意。
關於本文有什麼疑問可以在下面留言交流，如果您覺得本文對您有幫助，歡迎關注我的微博 或 ofollow,noindex" target="_blank">GitHub 。