由來
最近有個需求需要統計一個方法的耗時，這個方法前后各打出一條日志，類似於 [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 命令統計了耗時分布。
#!/bin/bash
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 問題可能完全沒有意義，換一種方案，原來的問題就全解決了。
在跟別人交流問題時，我一直把初始需求說清楚，避免此類問題，沒想到這次不知不覺就沉入其中了，下次一定注意。
關於本文有什么問題可以在下面留言交流，如果您覺得本文對您有幫助，可以點擊下面的 推薦 支持一下我，博客一直在更新，歡迎 關注。