解决问题，别扩展问题

由来

---

最近有个需求须要统计一个方法的耗时，这个方法先后各打出一条日志，相似于 [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 问题可能彻底没有意义，换一种方案，原来的问题就全解决了。

在跟别人交流问题时，我一直把初始需求说清楚，避免此类问题，没想到此次不知不觉就沉入其中了，下次必定注意。

关于本文有什么问题能够在下面留言交流，若是您以为本文对您有帮助，能够点击下面的 推荐 支持一下我，博客一直在更新，欢迎 关注。