解決問題的過程中，我們經常會遇到 "X-Y" 問題，最終撞了南牆才回頭，本文是我的一次踩坑經曆，介紹了一次連續日志時間差的求解過程。當然也介紹了一些 shell 技巧和 strace 的用法。
由來
最近有個需求需要統計一個方法的耗時，這個方法前後各打出一條日志，類似于
[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 問題可能完全沒有意義，換一種方案，原來的問題就全解決了。
在跟别人交流問題時，我一直把初始需求說清楚，避免此類問題，沒想到這次不知不覺就沉入其中了，下次一定注意。
關于本文有什麼問題可以在下面留言交流，如果您覺得本文對您有幫助，可以點選下面的
推薦
支援一下我，部落格一直在更新，歡迎
關注
。