由来
最近有个需求需要统计一个方法的耗时，这个方法前后各打出一条日志，类似于 [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脚本运行起来后，由于需要一次加载整个日志文件，再生成大数组，系统顿时严重卡顿(幸好早把日志传到了
