日志文件分析shell脚本六次提速过程
做性能调优，常常面对超大日志文件的分析问题，别指望什么vi或者ultraedit可以搞定。还得自己写代码。
题目的提出：
事情很简单，一个后台模块需要进行性能测试后的日志分析，这个后台模块进行转发，所以日志中同时有发送和接收的日志，示例如下：
[2012-07-23 14:15:20.734][PID.100][DEBUG]: Start Time:20120723141520730,callid:1-1987@191.8.2.157,title:INVITE sip:44636130000001@191.8.2.158:5060 SIP/2.0,cseq:1 INVITE
[2012-07-23 14:15:20.741][PID.100][DEBUG]: Send Message Time:20120723141520741,callid:1-1987@191.8.2.157,title:SIP/2.0 100 Trying,cseq:1 INVITE
[2012-07-23 14:15:20.826][PID.100][DEBUG]: End Time:20120723141520826,callid:1-1987@191.8.2.157,title:INVITE sip:44636130000001@191.8.2.158:5060 SIP/2.0,cseq:1 INVITE
[2012-07-23 14:15:20.849][PID.100][DEBUG]: Send Message Time:20120723141520849,callid:1-1987@191.8.2.157,title:SIP/2.0 180 Ringing,cseq:1 INVITE
[2012-07-23 14:15:20.851][PID.100][DEBUG]: Start Time:20120723141520851,callid:1-1987@191.8.2.157,title:PRACK sip:44636130000001@191.8.2.158:5060 SIP/2.0,cseq:2 PRACK
[2012-07-23 14:15:20.876][PID.100][DEBUG]: End Time:20120723141520876,callid:1-1987@191.8.2.157,title:PRACK sip:44636130000001@191.8.2.158:5060 SIP/2.0,cseq:2 PRACK
[2012-07-23 14:15:20.895][PID.100][DEBUG]: Send Message Time:20120723141520895,callid:1-1987@191.8.2.157,title:SIP/2.0 200 OK,cseq:2 PRACK
[2012-07-23 14:15:20.930][PID.100][DEBUG]: Send Message Time:20120723141520930,callid:1-1987@191.8.2.157,title:SIP/2.0 200 OK,cseq:1 INVITE
[2012-07-23 14:15:20.932][PID.100][DEBUG]: Start Time:20120723141520932,callid:1-1987@191.8.2.157,title:ACK sip:44636130000001@191.8.2.158:5060 SIP/2.0,cseq:3 ACK
[2012-07-23 14:15:20.971][PID.100][DEBUG]: End Time:20120723141520970,callid:1-1987@191.8.2.157,title:ACK sip:44636130000001@191.8.2.158:5060 SIP/2.0,cseq:3 ACK
[2012-07-23 14:16:20.928][PID.100][DEBUG]: Start Time:20120723141620928,callid:1-1987@191.8.2.157,title:BYE sip:44636130000001@191.8.2.158:5060 SIP/2.0,cseq:4 BYE
[2012-07-23 14:16:20.929][PID.100][DEBUG]: End Time:20120723141620929,callid:1-1987@191.8.2.157,title:BYE sip:44636130000001@191.8.2.158:5060 SIP/2.0,cseq:4 BYE
[2012-07-23 14:16:21.057][PID.100][DEBUG]: Send Message Time:20120723141621057,callid:1-1987@191.8.2.157,title:SIP/2.0 200 OK,cseq:4 BYE
[2012-07-23 14:15:20.825][PID.100][DEBUG]: Send Message Time:20120723141520825,callid:1-1987@191.8.2.158,title:INVITE sip:30000001@191.8.2.157:5060 SIP/2.0,cseq:1 INVITE
[2012-07-23 14:15:20.827][PID.100][DEBUG]: Start Time:20120723141520827,callid:1-1987@191.8.2.158,title:SIP/2.0 100 Trying,cseq:1 INVITE
[2012-07-23 14:15:20.828][PID.100][DEBUG]: End Time:20120723141520828,callid:1-1987@191.8.2.158,title:SIP/2.0 100 Trying,cseq:1 INVITE
[2012-07-23 14:15:20.829][PID.100][DEBUG]: Start Time:20120723141520828,callid:1-1987@191.8.2.158,title:SIP/2.0 180 Ringing,cseq:1 INVITE
[2012-07-23 14:15:20.829][PID.100][DEBUG]: End Time:20120723141520829,callid:1-1987@191.8.2.158,title:SIP/2.0 180 Ringing,cseq:1 INVITE
[2012-07-23 14:15:20.871][PID.100][DEBUG]: Send Message Time:20120723141520871,callid:1-1987@191.8.2.158,title:PRACK sip:30000001@191.8.2.157:5060 SIP/2.0,cseq:2 PRACK
[2012-07-23 14:15:20.873][PID.100][DEBUG]: Start Time:20120723141520872,callid:1-1987@191.8.2.158,title:SIP/2.0 200 OK,cseq:2 PRACK
[2012-07-23 14:15:20.873][PID.100][DEBUG]: Start Time:20120723141520873,callid:1-1987@191.8.2.158,title:SIP/2.0 200 OK,cseq:1 INVITE
[2012-07-23 14:15:20.874][PID.100][DEBUG]: End Time:20120723141520874,callid:1-1987@191.8.2.158,title:SIP/2.0 200 OK,cseq:1 INVITE
[2012-07-23 14:15:20.874][PID.100][DEBUG]: End Time:20120723141520874,callid:1-1987@191.8.2.158,title:SIP/2.0 200 OK,cseq:2 PRACK
[2012-07-23 14:15:20.965][PID.100][DEBUG]: Send Message Time:20120723141520965,callid:1-1987@191.8.2.158,title:ACK sip:30000001@191.8.2.157:5060 SIP/2.0,cseq:3 ACK
[2012-07-23 14:16:20.929][PID.100][DEBUG]: Send Message Time:20120723141620929,callid:1-1987@191.8.2.158,title:BYE sip:30000001@191.8.2.157:5060 SIP/2.0,cseq:4 BYE
[2012-07-23 14:16:20.930][PID.100][DEBUG]: Start Time:20120723141620930,callid:1-1987@191.8.2.158,title:SIP/2.0 200 OK,cseq:4 BYE
[2012-07-23 14:16:21.068][PID.100][DEBUG]: End Time:20120723141621068,callid:1-1987@191.8.2.158,title:SIP/2.0 200 OK,cseq:4 BYE
现在需要得到的是：
呼叫的各个步骤的次数；
查找开始了没结束的记录，检查哪些呼叫没有正常结束，然后对这些呼叫进行细节分析；
同时记录有结束没有开始的记录，这种情况通常没有，除非日志是半截的；
对呼叫的响应时间进行统计。
返回结果类似：
logfilename : TONGJI RESULT
INVITE:xxx
Trying:xxx
Ringing:xxx
PRACK:xxx
200 OK(1:INVITE):xxx
200 OK(2:PRACK):xxx
ACK:xxx
BYE:xxx
200 OK(3:BYE):xxx
callid:xxx
send INVITE:xxx
send 200 OK(BYE):xxx
cost time [0s--1s]: xxx
cost time [1s--2s]: xxx
cost time [2s--3s]: xxx
cost time [3s--4s]: xxx
cost time [4s-- ]: xxx
当然还会将有开始没结束或者有结束没开始的呼叫打印出来。
六次提速贴出脚本来就一大堆了，看也看不过来了，细节看后面的附件吧。只说算法和要点了。
版本一：
为了效率着想，尽可能使用c效率的awk，避免使用shell命令组合，那效率实在难以忍受。
在这个版本中，awk同时处理两个文件，但是遇到一个技术瓶颈，就是在awk中如何计算时间相减。找到了date可以实现相减，但是悲剧的是不知道如何将使用date相减的结果传递给awk的变量。挠头了半天，想出来一个馊主意：直接拼接字符串，输出到一个shell脚本中，然后再执行该脚本，生成结果文件，格式为：callid，消耗时间。
最后，悲催的发现生成的shell脚本不但很大，执行起来真的不是一般的慢，想想还要写一个脚本来对结果文件进行统计，算了吧，forget it。
参看一下生成脚本：
awk...{
etime=substr(arr1[i],index(arr1[i],"[")+1,index(arr1[i],"]")-index(arr1[i],"[")-1);
stime=substr($0,index($0,"[")+1,index($0,"]")-index($0,"[")-1);
print "st=`date +%s -d \"" stime "\"`";
print "et=`date +%s -d \"" etime "\"`";
print "printf \""callid1":\">>time.log";
print "echo \"$et-$st\" | bc>>time.log";
} file1 file2 |tee -a difftime.sh
chmod +x difftime.sh
./difftime.sh
这个版本的速度，怎么说呢，发起呼叫文件或结束呼叫文件大约4200条记录，你就算吃顿饭回来也未必能执行完。
版本二：
这个版本总算解决了在awk中将时间相减，并返回给awk的变量，于是改写了白痴的版本一，这样也就可以在一个脚本中实现呼叫的响应时间统计。
技术要点如下：
etime=substr(arr1[i],index(arr1[i],"[")+1,index(arr1[i],"]")-index(arr1[i],"[")-1);
stime=substr($0,index($0,"[")+1,index($0,"]")-index($0,"[")-1);
syscmd="st=`date +%s -d \""stime"\"`;et=`date +%s -d \""etime"\"`;echo \"$et-$st\" | bc";
##print syscmd;
syscmd|getline dualtime;
##print "dualtime:"dualtime;
这个版本测试了一下，当然比上一个版本强多了，不过也差不多需要一次大便的时间，要知道这才4200多条记录，如果10w条记录甚至更多呢，那你需要100000/4200=23.8次大便才能完成。这事不靠谱。
版本三：
再次改进，将预处理的程度加深，最终开始呼叫文件和结束呼叫文件只剩下时间和呼叫ID两个字段，避免了awk中大量的字符串运算。这个没啥特别的技术，参考：
grep 'SIP/2.0,cseq:1 INVITE' $IN_FILE|grep 'Send Message'|awk -F"@" '{print $1}'>$START_FILE.tmp
grep 'SIP/2.0 200 OK,cseq:4 BYE' $IN_FILE|grep 'Send Message'|awk -F"@" '{print $1}' >$STOP_FILE.tmp
awk -F":" '{print(substr($0,2,23)","$NF);}' $START_FILE.tmp>$START_FILE
awk -F":" '{print(substr($0,2,23)","$NF);}' $STOP_FILE.tmp>$STOP_FILE
测试了一下速度：
4289/122=35.15573770491803条/秒
100000/35.15573770491803=2844.48589414782秒/60=47.408098235797分
介个。。。。。。革命尚未成功，继续努力吧。
版本四：
开始和结束呼叫两个文件都是4289条记录，每次都需要对比，次数就需要4289*4289=18395521次，很多记录是已经比对成功了的，都是无效比对的。所以改进算法，将stopfile导入数组后，用一个变量记录数组匹配上的最新位置，一旦有匹配上就和未匹配上的最顶值交换，循环就从匹配上的最新位置加一再开始，由于两个文件基本上是按照时间排序的，所以实际比对的次数可能也就和之前的零头相当，估计不超过5000次。
技术要点参考：
for(i=y;i<=x;i++){
if(arr2[i]==$2){
......
sw=arr2[y];
arr2[y]=arr2[i];
arr2[i]=sw;
y=y+1;
break;
}
}
测试速度：
4289/112=38.29464285714286
100000/38.29464285714286=2611秒
2611/60=43.51666666666667分
还是不能接受，看来数据量不够大，效果不明显，最大的瓶颈必然不是awk中的比对。想起来了，因为两个文件的数据都基本上是位置相一致的，加上匹配上就break出了for循环，所以实际循环数比之前推算的少很多。
版本五：
改进：
怀疑开启子进程计算时间相减导致效率很低，所以预先处理时间，生成秒值，awk中就直接减就行了
另外将截取时间的方法写成了硬编码：
substr($0,index($0,"[")+1,index($0,"]")-index($0,"[")-1); 改为了：substr($0,2,23)
读书人，别那么迂腐，此时不用硬编码更待何时？
技术要点：
awk -F":" '{print(substr($0,2,23)","$NF);}' $START_FILE.tmp1>$START_FILE.tmp2
awk -F":" '{print(substr($0,2,23)","$NF);}' $STOP_FILE.tmp1>$STOP_FILE.tmp2
awk -F"," '{syscmd="date +%s -d \""$1"\"";syscmd|getline var;print var","$2}' $START_FILE.tmp2>$START_FILE
awk -F"," '{syscmd="date +%s -d \""$1"\"";syscmd|getline var;print var","$2}' $STOP_FILE.tmp2>$STOP_FILE
速度虽然有所提高，但是没有质的改变，不过总算进了30分钟，但是实际情况中10w条记录几乎是下限，得100w级别才有实际价值：
4289/76=56.43421052631579
100000/56.43421052631579=1771.974819305199/60=29.53291365508665分
终极版本六：
现在已经非常清楚了，就是时间相减导致了无法实现速度质的提升，date的方法不够用。土法上马，降低严谨程度，直接awk中计算一个出来，减一个秒值出来，毫秒对于我没有意义。
技术要点：
et=substr(arr1[i],9,2)*86400+substr(arr1[i],12,2)*3600+substr(arr1[i],15,2)*60+substr(arr1[i],18,2);
st=substr($1,9,2)*86400+substr($1,12,2)*3600+substr($1,15,2)*60+substr($1,18,2);
dualtime=et-st;
测试速度，果然耳目一新：
4289/3=1429.666666666667
100000/1429.666666666667=69.94637444625785秒
也就是说如果资源够用，100w条记录也能一个小时左右就搞定，这个差不多能满足需求了。
效率、代码严谨和规范，每件事都重要，但是总得有取舍，都重要里面也有最重要的。
GOD BLESS U !!!
附件：
http://download.csdn.net/detail/testingba/4450278
