2010年10月份左右

三天两头出现服务器飘红的情况,cpu高,内存有时出现用光的情况。查看线上服务器一段时间,也没有特别的错误日志,慢请求也是不明显的,在服务器出问题的时间,什么请求都慢,而且多,很难看出哪些请求是有问题的。 在 监控系统中发现,单台应用的memcache服务器get最高达到 2000/s,为在短时间内解决问题,直接让SA加了两台服务器。 似乎有所好转,红的频率有所降低,但在一个星期总会出现。在监控中也似乎没什么发现,后来在应用服务器上查看请求数时发现,负载均衡后还是不太均衡的。有 的服务器是3000/m,有的服务器是1000/m.和SA联系后,发现在一组负载均衡上只配置了部分web应用,所以这部分的web应用承载了一半的请 求。


2010年11-12月份左右

自上次解决负载均衡导致服务器飘红问题后,房产应用服务器还是会时不时出现cpu负载过高的问题,并经常在半夜0点后,偶尔也在白天。

开始查找问题原因。

1. 哪些请求太慢?找出了一些慢请求,结果分析后,找不出导致慢的代码,而这些慢的请求也是在服务出问题时出现的。
2. Cpu高时内存是正常的,开始怀疑是不是因为jvm不停地full GC引起的,和妙子分析服务器的gc情况,没发现问题,即使服务器cpu高时GC也是正常的。
3. 会不会是搜索的原因。突然觉得非常有可能呀,请求长时间挂着,当然占cpu啦。

分析情况如下:
以下是一个小时的单台isearch merge的情况。
[admin@merge1 httpd]$ grep 2010:01 access_merge_101220.log|wc -l 359232 [admin@merge1 httpd]$ grep 2010:10 access_merge_101220.log|wc -l 233854 [admin@merge1 httpd]$ grep 2010:01 access_merge_101221.log|wc -l 94702 [admin@merge1 httpd]$ grep 2010:10 access_merge_101221.log|wc -l 257893 [admin@merge1 httpd]$ grep 2010:01 access_merge_101226.log|wc -l 599050 [admin@merge1 httpd]$ grep 2010:10 access_merge_101226.log|wc -l 246161 [admin@merge1 httpd]$ grep 2010:01 access_merge_101227.log|wc -l 414787 [admin@merge1 httpd]$ grep 2010:10 access_merge_101227.log|wc -l 218420

这是房merge1上isearch的访问日志数。20号和26号是应用服务器在半夜(1点)cpu负载过高的时间。

应用在正常情况(这里取的时间是上午10点):
[admin@merge1 httpd]$ grep 2010:10 access_merge_101220.log|wc -l 233854 [admin@merge1 httpd]$ grep 2010:10 access_merge_101221.log|wc -l 257893 [admin@merge1 httpd]$ grep 2010:10 access_merge_101226.log|wc -l 246161 [admin@merge1 httpd]$ grep 2010:10 access_merge_101227.log|wc -l 218420

所以正常 250000*2/60/60==139qps

非正常半夜1点(20号和26号)情况:
[admin@merge1 httpd]$ grep 2010:01 access_merge_101220.log|wc -l 359232 [admin@merge1 httpd]$ grep 2010:01 access_merge_101226.log|wc -l 599050

所以非正常 约500000*2/60/60==287qps

正常半夜1点情况:
[admin@merge1 httpd]$ grep 2010:01 access_merge_101221.log|wc -l 94702 [admin@merge1 httpd]$ grep 2010:01 access_merge_101227.log|wc -l 414787

这两天的请求数是有差别的,而这两天服务器是正常的,只能说明它撑住了。
可以看出,isearch大约能撑住的qps是,供参考:
能撑住400000*2/60/60==222qps

上面的数字,它反应了搜索服务器和应用服务器的性能。应用服务器对isearch的请求越来越多时,isearch开始出现超时,当然应用服务 器从isearch那里取得数据所花费的时间也越来越多,应用端长挂着(因为对isearch是同步),cpu被占着,负载当然高了。

可以理解成isearch已经不能负荷了。

为什么晚上不能负荷?

1. 现在应用有老应用和新应用
2. 有大量的安全测试,对isearch的请求都是她妈的<script>,xss,<a> 这种东西

a) 半夜健全帮我干的活:
[web@oldfang1 logs]$ grep 2010:01 koubei-usertrack.log-20101223 | grep /fang/listsell.html | grep alibaba |wc -l 4705 [web@oldfang1 logs]$ grep 2010:01 koubei-usertrack.log-20101226 | grep /fang/listsell.html | grep alibaba |wc -l 50917 26号半夜一点请求老应用list就这么多。四台老应用不是要200,000一小时,还不算其它的爬虫。

[root@tfang10 logs]# grep 2010:01 koubei-usertrack.log-20101222 | grep /fang/listsell.html |wc -l 1983 [root@tfang10 logs]# grep 2010:01 koubei-usertrack.log-20101226 | grep /fang/listsell.html |wc -l 2222 26号半夜一点对新应用没有请求

b) 正常情况下对出售list请求:
[root@tfang10 logs]# grep 2010:10 koubei-usertrack.log-20101222 | grep /fang/listsell.html |wc -l 11639 [root@tfang10 logs]# grep 2010:14 koubei-usertrack.log-20101222 | grep /fang/listsell.html |wc -l 13077 [root@tfang10 logs]# grep 2010:14 koubei-usertrack.log-20101224 | grep /fang/listsell.html |wc -l 6911 [root@tfang10 logs]# grep 2010:10 koubei-usertrack.log-20101224 | grep /fang/listsell.html |wc -l 6980 正常情况下,新应用对出售list请求也就这么点,10台也就120,000一小时。

[web@oldfang1 logs]$ grep 2010:10 koubei-usertrack.log-20101226 | grep /fang/listsell.html |wc -l 2300 [web@oldfang1 logs]$ grep 2010:10 koubei-usertrack.log-20101223 | grep /fang/listsell.html |wc -l 3425 正常情况下,老应用请求是很少的,4台也就10,000一小时

26号晚上对出售isearch请求就远远大于正常情况下对isearch请求.

提议解决方案:
1. 我要应用端,控制对isearch的请求,如果关键字中出现<script>,xss,<a>,不对isearch发起请求。
2. 看看能不能在服务上控制对安全检测,即使qps少点也是好的嘛

 

基本确定是这个问题引起应用服务器的问题,如果我们把这个问题解决了还是有问题,我们再来排查问题,希望就是它了。

 


2011年1月

近来观察,半夜已经没问题了。 日志也比较正常了。

今天tfang1在9点半的时候出现问题。排除了其它原因,只能再查看慢的请求了。查看9点半的日志,请求超过1s的,当然查最慢的。 grep 2011:09:3 koubei-usertrack.log-20110116|awk '{if($1>1000) print $0}' >~/broker.log 都是经纪人对房源的操作。经纪人说操作很慢,的确定很慢。这些url请求是可参考的,非常集中了,不像刚找问题时,找慢请求,一找乱七八糟什么都有,连取个cms文件,取个Cache都慢。

相信这是cpu高的最后一个问题。阿门。

在检查管理的列表中,有一个控制重复提交的安全标签,一个房源因操作多,而用到了五次,一页10个房源。一个list请求,至少 请求50次.而这个安全标签是用到了cache.问题就在这里,cache连接太多,在建立和释放链接时,用掉了太多的系统资源,cpu受不起了。

在Detail页面中也发现,为了过滤掉敏感词汇,对7个文本运用cache处理敏感词,又是一个消耗。

回顾:以前出现过memcache的客户端连接不够用的情况,而当然的解决办法是直接调大客户端的连接。现在想来其它是一种隐藏错误的做法。