解決問題，別擴展問題

由來

---

最近有個需求須要統計一個方法的耗時，這個方法先後各打出一條日誌，相似於 [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 問題可能徹底沒有意義，換一種方案，原來的問題就全解決了。

在跟別人交流問題時，我一直把初始需求說清楚，避免此類問題，沒想到此次不知不覺就沉入其中了，下次必定注意。

關於本文有什麼問題能夠在下面留言交流，若是您以爲本文對您有幫助，能夠點擊下面的 推薦 支持一下我，博客一直在更新，歡迎 關注。