今天在把app proxy平均响应时间加入支撑平台时发现一个问题。同事写的shell脚本和我之前写的shell脚本，所有的app统计结果基本都一致，唯有通知app不一样（同事写的shell脚本, 通知app的平均响应时间居然提高了3倍），难道是我之前写的统计有误？又或者是经过二周，通知系统的响应时间确实提高啦？不肯相信，于是查找原因。

Log日志数据结构

2011-11-10 20:05:42,037 INFO [ProxyLogger] LogInfo [accessTime=2011-11-10 20:05:42, totalTime=15, accessType=2, app=blog, requestUrl =http://proxy.i.sohu.com/blog/home/entry/edit.htm?_xpt=eWV6aTY3MDUwM0Bzb2h1LmNvbQ==&service=blog&pathinfo=home/entry/edit.htm&id=190 977755, resultCode=200, from=2] 2011-11-10 20:05:46,765 INFO [ProxyLogger] LogInfo [accessTime=2011-11-10 20:05:46, totalTime=7, accessType=2, app=setting, requestU rl=http://proxy.i.sohu.com/setting/home/privacy.htm?_xpt=bWFveml5dW5Ac29odS5jb20=&service=setting&pathinfo=home/privacy.htm, resultC ode=200, from=2] 2011-11-10 20:05:47,925 INFO [ProxyLogger] LogInfo [accessTime=2011-11-10 20:05:47, totalTime=14, accessType=2, app=profile, request Url=http://proxy.i.sohu.com/profile/home/swfUploadIcon.htm?_xpt=cXExNTU2MjA1NTYwQHNvaHUuY29t&service=profile&pathinfo=home/swfUpload Icon.htm, resultCode=200, from=2] 2011-11-10 20:05:50,039 INFO [ProxyLogger] LogInfo [accessTime=2011-11-10 20:05:50, totalTime=8, accessType=2, app=request, requestU rl=http://proxy.i.sohu.com/request/home/inform/deal.htm?_xpt=bGluaGFpc2hlbmNodTEyM0Bzb2h1LmNvbQ==&service=request&pathinfo=home/info rm/deal.htm&id=30293269&type=inform_circle, resultCode=200, from=2] 2011-11-10 20:05:56,558 INFO [ProxyLogger] LogInfo [accessTime=2011-11-10 20:05:56, totalTime=8, accessType=2, app=blog, requestUrl= http://proxy.i.sohu.com/blog/home/entry/index.htm?_xpt=MTY0MzIzOTEwNkBxcS5jb20=&service=blog&pathinfo=home/entry/index.htm, resultCo de=200, from=2] 2011-11-10 20:05:57,361 INFO [ProxyLogger] LogInfo [accessTime=2011-11-10 20:05:57, totalTime=14, accessType=2, app=album, requestUr l=http://proxy.i.sohu.com/album/home/latest/?_xpt=eGluZ2tvbmd4aW5saW5nQHNvaHUuY29t&service=album&pathinfo=home/latest/, resultCode=2 00, from=2]

shell脚本

DATE=`date +"%Y%m%d" -d "-1 days"` if [ "$1" != "" ];then DATE=$1 fi echo "date:"$DATE apps=`cat proxylog.log.$DATE |awk -F"," '{print $5}'|awk -F"=" '{++s[$2]}END{for(a in s){print a}}'` for app in $apps;do #同事写的 stats=`cat proxylog.log.$DATE |grep $app |awk -F"," '{print $3}'|awk -F"=" '{i++;t=t+$2}END{printf int(t/i)}'` echo "$app $stats" #我原来写的 stats2=`cat proxylog.log.$DATE |awk -v app=$app -F , '$5==" app="app {print$3}'|awk -F = '{sum+=$2;j++};END{print int(sum/(j))}'` echo "$app $stats2" done

统计结果

[@105.165 suc-home]# sh proxylog.sh

date:20111110

album 53

album 53

blog 14

blog 14

request 41

request 135
discuss 90

discuss 90

guestbook 19

guestbook 19

scomment 17

scomment 17

setting 7

setting 7

profile 38

profile 38

video 10

video 10



原因分析
一开始以为是grep 和awk的区别，后来发现不是。抽了半个多小时，发现同事的脚本

stats=`cat proxylog.log.$DATE |grep $app |awk -F"," '{print $3}'|awk -F"=" '{i++;t=t+$2}END{printf int(t/i)}'` #app为blog,mblog,album,request等 #所以grep $app时为匹配所有request. 2011-11-10 20:06:02,930 INFO [ProxyLogger] LogInfo [accessTime=2011-11-10 20:06:02, totalTime=7, accessType=2, app=blog, requestUrl= http://proxy.i.sohu.com/blog/home/entry/index.htm?_xpt=MTMyNTYyNDY4OUBxcS5jb20=&service=blog&pathinfo=home/entry/index.htm, resultCo de=200, from=2]

我们可以看到log数据文件app=blog时也加入统计了，所以一平均就是41了，因为每条log都有requestUrl关键字，所以相当于统计了所有app的平均响应时间。


记录一下，备忘。Awk还是很强大的，linux日志统计必备之佳品呀。