这几天有个客户的系统很慢。要调查原因,应该是DB2死锁的问题。但是当时没抓到死锁,所以没能够找到导致死锁的sql预计。这样只能换一个方法,从中间件入手,找最慢的URL。然后通过url找到相关的应用,应用找sql。
前提是IHS日志的格式有统计记录页面时间,例如:
LogFormat "%h %t %u %v:%p(%P) %m-%H %TSec. %>s %b \"%U\" \"%q\"" common
在系统出问题的时段找,只能找到几百秒-一千多秒的。貌似这些都是受害的URL。最后写了一个AWK脚本来把返回时间大于N秒的输出到一个文件:
cat access*.log |awk '{sub(/Sec./," Sec.");if ($7>10) {print $1,$2,$3,$5,$6,$7,$8,$9,$10,$11,$12}}' >10out.txt
最后发现了
192.168.1.9 [26/Mar/2011:14:35:51 +0800] - ServerName:80(7268) POST-HTTP/1.1 19950Sec. 400 2736 "/order/orderQuery.do" ""
总结统计返回时间IHS的日志,是在整个URL处理完毕的时候才会输出日志。如果我在14:35:51附近的时候是找不到这个日志的。这行日志实在14:35:51之后19950秒才输出。大概是8点35分附近。所以故障分析日志,扩大一下调查日志的范围,才能找到更多有用的资料。