由來

最近有個需求需要統計一個方法的耗時，這個方法前後各打出一條日誌，類似於 [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 為鍵，

這樣，寫出的腳本就是這樣：

腳本

#!/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 問題可能完全沒有意義，換一種方案，原來的問題就全解決了。

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

關於本文有什麽問題可以在下面留言交流，如果您覺得本文對您有幫助，可以點擊下面的 推薦 支持一下我，博客一直在更新，歡迎 關註。

解決問題，別擴展問題