网站卡怎么办

网站卡怎么办。。估计这个词搜索量挺高的。
最近刚好碰到一起很二的网站卡的事情,然后花了点时间解决了。然后回头看觉得自己解决的过程还很二。记下来,或许对大家有用。

前奏是这样的
小编:好卡……网站好卡……
工程师:我这儿好好的。
小编:……

又过了一会儿

小编:真的好卡,动都动不了……
工程师:蛤,真的吗?哪里卡?
小编:哪都卡,特别是看贴回贴,然后还有私信。
工程师:那我看看。
小编:……

又过了一会儿
工程师:我看代码逻辑也对啊……是不是你的网络问题?
小编:你看你看又卡了……你看,这个什么502 Bad Gateway是什么意思啊。

啊,终于有一个靠谱的出错信息了。
502,然后找到了这个信息。

http://jingyan.baidu.com/article/da1091fbf121df027949d642.html
Nginx 502 Bad Gateway的含义是请求的PHP-CGI已经执行,但是由于某种原因(一般是读取资源的问题)没有执行完毕而导致PHP-CGI进程终止,一般来说Nginx 502 Bad Gateway和php-fpm.conf的设置有关。
php-fpm.conf有两个至关重要的参数,一个是max_children,另一个是request_terminate_timeout,但是这个值不是通用的,而是需要自己计算的。
在安装好使用过程中出现502问题,一般是因为默认php-cgi进程是5个,可能因为phpcgi进程不够用而造成502,需要修改/usr/local/php/etc/php-fpm.conf 将其中的max_children值适当增加。

这意思是PHP的线程池不够用的节奏?于是修改php-fpm.conf,打开了pm.status,然后盯着看。

有的时候感觉status刷得很慢。

pool:                 www
process manager:      dynamic
start time:           11/Jun/2014:14:49:41 +0800
start since:          8045
accepted conn:        348066
listen queue:         0
max listen queue:     0
listen queue len:     0
idle processes:       0
active processes:     303
total processes:      303
max active processes: 352
max children reached: 0

然后慢慢变得不那么卡,变成类似这样

pool:                 www
process manager:      dynamic
start time:           11/Jun/2014:14:49:41 +0800
start since:          8164
accepted conn:        353137
listen queue:         0
max listen queue:     0
listen queue len:     0
idle processes:       123
active processes:     9
total processes:      132
max active processes: 352
max children reached: 0

观察到的现象是在卡的时候,空闲PHP为0了。。然后慢慢不卡,然后空闲进程多一些起来。

php一直在处理东西,没结束,php的线程池就会被一直用掉,然后直到空闲线程为0.
处理什么东西会很久?查看php的slow log。

查看了slow log,发现很多是慢在数据库操作环节。嗯,数据库问题。看数据库。
进mysql,show processlist 之后发现有一些select似乎蛮慢的。看表结构,没索引。。于是建索引。

再观察,没效果。
但发现个新现象:就是有的事务在commit的时候花了非常多的时间。然后其它的都在排队。于是猜测是哪个事务写得不对,比如在事务里做网络连接之类的事情导致事务的时间太长。
所以就写了个日志,在commit的时候记录这个事务的时间,然后再用debug_backtrace找到这个事务是哪个方法调用的。然后等着看日志。

然后日志抓到了,果然有一个二货的逻辑可以优化。
优化是这么多的,在事务中把多个update xxx set xxx = 1 where id = xxx 合并成一个update xxx set xxx = 1 where id in(xxx,xxx),然后在事务中居然还有sphinx操作。于是把非sql操作的丢到事务之外。
再观察。

“曾经真的以为人生就这样了,平静的心难以再有浪潮”
以为故事就这样结束了有没有。

不过问题还在!优化了这个事务之后,发现这个事务仍然执行了很长时间。不科学!

重新看那个日志。

11:01:55 count 10, time=0.025902032852173, time2=0.090005159378052, time3=0.026114940643311
11:01:57 count 1, time=0.016336917877197, time2=0.030117988586426, time3=0.016648054122925
11:03:23 count 1, time=74.487523078918, time2=74.501142024994, time3=74.487838983536
11:03:23 count 30, time=71.291594982147, time2=71.310960054398, time3=71.292006015778
11:03:23 count 1, time=70.450335979462, time2=70.471060991287, time3=70.450758934021
11:03:24 count 5, time=58.812111139297, time2=58.827339172363, time3=58.812895059586
11:03:24 count 1, time=62.953996896744, time2=62.972425937653, time3=62.954273939133
11:03:24 count 4, time=62.915053844452, time2=62.934178829193, time3=62.915548801422
11:03:24 count 15, time=57.812154054642, time2=57.827141046524, time3=57.812452077866
11:03:24 count 10, time=56.796147823334, time2=56.810019016266, time3=56.79643201828
11:03:24 count 4, time=59.805339097977, time2=59.825000047684, time3=59.805682182312
11:03:24 count 3, time=50.887267112732, time2=50.904989957809, time3=50.887581110001
11:03:24 count 2, time=57.792289972305, time2=57.814527988434, time3=57.79256606102
11:03:24 count 2, time=50.540719985962, time2=50.568138122559, time3=50.54171204567
11:03:24 count 4, time=31.225328207016, time2=31.244138002396, time3=31.225693225861
11:03:24 count 1, time=42.314253091812, time2=42.333055019379, time3=42.31564116478
11:03:24 count 30, time=20.184834003448, time2=20.236382007599, time3=20.185832023621
11:03:24 count 2, time=0.42022705078125, time2=0.43663287162781, time3=0.42063689231873
11:03:25 count 3, time=0.071909189224243, time2=0.091092109680176, time3=0.073103189468384
11:03:25 count 1, time=0.072575092315674, time2=0.098610162734985, time3=0.074020147323608
11:03:26 count 50, time=0.26183581352234, time2=0.27783989906311, time3=0.26212692260742

一批sql操作的执行时间都非常长。然后他们都在差不多11:03:24左右完成,但看到他们的执行时长不一致。也就是实际的情况是,这些sql陆续来到mysql要求处理,但mysql没空答理他们,但突然在11:03:24的时候全部处理完。

情况像是mysql被什么东西压得处理不过来,于是这些事情被等到mysql有力气了再处理。。于是php也跟着处理不过来,于是502……

重新看show processlist

然后发现这么个有意思的事情。。
QQ20140618-1
都是写入操作有没有。

这种情况又不是每条sql都这样。隔一段时间就来一次的感觉。
半瓶连续查了几次,追踪同一个sql的执行情况的时候,发现一个update,在写入数据花了40秒,然后query end花了20秒以上

然后哥哥怀疑磁盘io有问题,写入效率有问题之类,或是磁盘快挂了,然后raid在恢复数据之类,造成磁盘io低。但这种应该是长时间的现象,而不是隔段时间卡。。

然后就iostat了。

iostat -k -x -d 2 10

观察到会每5分钟左右,每秒写入50m左右的数据。。持续一分钟左右。这样的话大约在1.5g,一分钟是3G。
换句话说,系统每5分钟左右,会往磁盘里写入1.5-3G的数据。。

现在我的疑问是,谁在写这个数据?
没什么工具。于是我开了三个窗口。
一个窗口在iostat观察。另一个窗口查看top。再一个窗口随时show processlist;

然后就观察到神奇的现象。
写压力大的时候,redis-server跑在最前面,超过了mysql,这时候mysql里的sql开始增多。
然后redis的cpu下来的时候,mysql里的sql会继续增加一阵子,然后很快降低。

每隔几分钟均是如此。

猜redis在做什么事情吃cpu和磁盘。

婷婷说有一个从redis转存到mysql的定时程序。但发现停到这个crontab之后还是一样出现这个问题。
然后我再观察了一下。发现出现这个问题的时候,并不是redis的主进程在吃cpu和io,而是一个子进程在做这件事情,然后做完这件事情之后这个子进程就结束了。

然后习惯性先看redis配置。。发现了这么几行可疑的。

redis-config

也就是如果在60秒内积累到10000个key被修改,或是5分钟内积累有10个key被修改,就会触发一次持久化。

这个持久化是把内存里的数据完全持久化。而没有增量持久化之类的事情。而且还配置了保存string类型的时候要压缩。

所以我猜redis里的数据量很大,然后可能修改很频繁,所以会频繁持久化,然后在每次持久化的时候,要写入很大的文件,然后又需要压缩。所以表现出来会是又吃cpu又吃io。
然后mysql因为资源被redis用掉,所以在等着。然后php因为mysql在等着, 所以php线程池里的空闲连接数变少。然后因为这个持续时间挺长,所以新来的php就502 bad gateway了。

下一步要证实猜想。
redis的数据量大。
查看redis的转存文件dump.rdb大小。1.7G…
再看redis在做什么事情。

./redis-cli monitor > redis.log

 
然后看到一大堆的SESSION操作。

大约10秒有2700个redis操作,其中一半是session操作,然后其中的一半是写入操作。

现在问题能确定了。PHP使用redis做为session存储。
根据配置,5分钟内redis超过10个key被改动,所以这时候触发了一次转存。
吃cpu、吃io…

然后现在就要下手解决问题了。
1. 新启一个redis,不配置持久化。将php session指到这个redis上。
2. 旧redis因为数据量非常大了,转存非常耗时,不适合每5分钟操作一次。要改为12小时或24小时转存一次。
3. 将单redis设置为主从,在从库上做持久化,主库上不做持久化。

1. 带来的结果将是服务器上的session将丢失,重新登录就好。
2. 风险是如果当机,可能丢失24小时的数据,原先最多丢失15分钟的数据。
3. 未实施所以暂时不评估风险

可行。

于是复制redis配置,改之。启之。
改php.ini配置,kill -USR2 php-fpm之。
进旧redis-cli, config set save “86400 1 43200 10000”

然后。。药到病除。。

redis-log

但现在回过头看。我排除故障的方法是有问题的。。因为在发现redis吃cpu和io的时候,没有第一时间去看redis日志有没有!直接第一时间去看redis日志就会处理得更快一些。。

太二了……太丢人了……

但总的说来,处理网站卡的方法很多。但首先是要找对问题,比如我第一次找问题就找错了。然后对症下药。不是啥事情都提高mysql连接数,php进程数就能搞定的。

Copyright © 2014. All Rights Reserved.

发表评论

电子邮件地址不会被公开。 必填项已用*标注