PHP升级导致系统负载过高问题分析

大家在上次的技术分享会中（PPT内容请回复 "4"）提出了若干疑问，真的很赞！做技术嘛就是要刨根问底，由于一些是延伸出的扩展问题，所以鉴于时间限制当时并未细聊，本篇将展开讨论各个疑点，是文章 "4" 中的案例完整版

---------------------------------------

背景

据XX部门兄弟反应, 其在将PHP从5.3.8 升级到5.5.13 时, 开始运行正常, 运行一段时间后, 系统负载变高,达到200%以上, 从netstat看到大量连接处在CLOSE_WAIT状态。 最终导致系统不可用, 将PHP 回滚到5.3. 8 后, 一切正常。


php-fpm 配置文件除了由版本引起的差异外， 没做任何改变。


猜想

根据TCP关闭连接的流程图：



可以看到， 一个处于连通状态（ESTABLISHED）的连接， 当接收到FIN数据包（对方调用close）后，TCP 连接的状态由ESTABLISHED变为CLOSE_WAIT，等待应用调用close（即发送FIN给对方）。


因此我怀疑PHP由于某种原因被堵塞住（比如数据库等资源太慢），导致请求超时， nginx 主动close连接，而PHP 程序由于一直堵塞，导致其无法调用close，造成大量TCP连接处于CLOSE_WAIT状态。


由于当时没有故障现场， 因此我们挑选一台机器，将PHP5.5重新上线，等待故障现象重现，我计划问题重现时， 用strace 看下进程的系统调用，找出PHP进程到底堵塞在哪里。


分析

  1. Strace

周一将PHP5.5.13上线后， 周三大约上午9：30左右，系统负载飙升至200%以上， 立刻用strace 查看，结果没有发现任何堵塞的情况，却发现另一个异常现象：write函数调用失败

当PHP调用write返回响应时，结果报错：Brokenpipe，这说明TCP连接其实已经关闭。PHP并没有堵塞住，这跟我猜想的完全不同，一时想不明白为什么PHP会write 一个关闭了的连接，于是我先用sar 将当前的系统状态保持起来，包括磁盘，内存，网卡，CPU，中断，上下文切换等，留待以后慢慢分析。


分析sar的结果， 发现内存，CPU基本没有什么大的变化， 网卡流量明显降低，上下文切换（cswch/s）明显升高。网卡流量降低可以理解，因为当前系统已不能正常返回响应，但上下文切换（cswch/s）升高却不知道什么原因。


sar的结果暂时没有什么思路， 继续分析strace的结果。Brokenpipe说明连接早已经被对方关闭，难道是nginx超时了？看一下从accept连接到关闭连接的整个流程：

从accept 接受一个socket， 到read 读取数据一直正常， 但调用write当返回响应时，却报错Brokenpipe，从accept到write 一共花费大约1ms ，这段时间内nginx肯定是不会超时的！那为什么连接会关闭呢？我们用tcpdump抓包看下网络到底发生了什么。


  1. Tcpdump

用tcpdump 抓包，由于数据量太大， 我只选择了一台Nginx 的IP10.121.96.200，抓包并传回到本地用wireshark打开（wireshark便于分析），发现网络已经一团糟：

上图是tcp.port == 61029 的过滤结果，10.121.96.200是NGINX的IP， 10.121.96.206 是PHP的IP，后面为了方便直接用NGINX，PHP 来代称这两台机器。


异常1： 从图上可以看到， 开始NGINX向PHP发送SYN， 这是TCP创建连接三次握手的第一次， 然后PHP响应ACK， 这里PHP应该响应SYN+ACK 才是正确的，acknumber 是3646825320 也跟NGINX 发的SYN的序列号对应不起来，因此接下来NGINX 返回RST，直接重置了连接。


异常2： 先不管异常1， 我们继续往下看， 第4个数据包，过了3s后，nginx 重传了SYN包，这时PHP响应SYN+ACK， 序列号也能对应上，NGINX 回应ACK，三次握手完成，连接成功建立。然后NGINX向PHP发送HTTP请求，到了第9个包， NGINX发送FIN 关闭连接，而PHP除了返回对应的ACK外，没有返回任何东西：没有返回响应数据（len=0），也没有返回FIN来关闭连接。从AbsTime字段可以看到第8,9包之间相隔2s，因此合理推测NINGX应该是2s后超时，主动关闭了连接， PHP什么也没做，此时PHP机器上连接一定处于CLOSE_WAIT状态。


异常3： 继续看下面的数据包， 第11个数据包，又是一个SYN包， 这应该是一个新的连接，从时间上看， 距离上一个包1分钟多， 说明NGINX 复用（reuse）了这个端口（61029）。 但是从异常2可以知道， 此时PHP上的连接还处于CLOSE_WAIT状态， 接收到SYN后，只是返回了ACK，并且acknumber=1013848495，说明这个ACK确实是上一个连接的；同异常1， NGINX返回RST，重置了连接。


从抓包结果可以得出结论：PHP 上大量连接一直处于CLOSE_WAIT状态， 这时NGINX复用端口新建连接， PHP由于还处于CLOSE_WAIT状态， 直接返回了ACK， NGINX 期待返回的是SYN+ACK， 由于不符合预期NGINX直接返回RST重置连接， 连接重置后PHP上的CLOSE_WAIT就消失了。3s后NGINX重传SYN， 成功建立连接，发送请求，超时后close连接， PHP什么也没做，又变为CLOSE_WAIT状态， 一段时间后NGINX 复用端口新建连接……如此循环往复。


  1. 突破

那么问题是， PHP机器是怎么到达这种循环往复的状态呢？ 总有成因吧？到目前为止， 我们已经知道PHP 机器当前的状态， 从抓包来看， PHP处于CLOSE_WAIT 状态， 并且不响应NGINX的请求， 从strace结果来看， PHP没有堵塞，也在处理响应， 但是在返回响应的时候， 连接却早已经被NGINX 关闭。这两种结果明显矛盾！


此时， 没有任何其他思路， 走了很多弯路， 首先怀疑是网卡问题， ifconfig/ethtool看网卡状态， dropped ， errors 都是正常范围，又怀疑是TCP bug，但是我用SSH登录却没有任何问题，SSH也很正常，TCP这么容易出BUG也不太可能，因此确定一定不是TCP 及底层的问题，问题仍然出在PHP 上。


我突然想到， 可以将strace 的结果和tcpdump的结果对应起来， 从strace 中选取一个（IP，PORT）， 查看其对应tcpdump 的结果。 于是同时运行strace， tcpdump。选取strace 的一个NGINX IP，PORT：

1403674216.729752 accept(0, {sa_family=AF_INET, sin_port=htons(6470), sin_addr=inet_addr("10.121.96.200")}, [2688649527312]) = 4

从tcpdump的结果过滤host10.121.96.200 and port 6470 :

13:27:57.942284 IP 10.121.96.200.6470 > 10.121.96.206.9000: S3965696332:3965696332(0) win 5840 <mss 1460,nop,nop,sackOK,nop,wscale 7>

1403674216.729752为accept 调用时的时间戳， 转化为时间就是：WedJun 25 13:30:16 CST 2014，而tcpdump发起连接的时间却是13:27:57。accept 调用比接收到SYN晚了2分钟多。到这里我立刻明白连接被积压在队列里了，等到2分钟后， PHP才调用accept 从队列获取一个连接，而此时这个连接早已经因为超时被NGINX关闭了，因此PHP 返回响应调用write时，会报Broken pipe 。


连接队列的大小由backlog控制（listen 系统调用的第二个参数），PHP5.5 默认为65535，而PHP5.3.8 默认为128，我们都是用的默认值，因此这两个值是不同的。由于PHP5.5 使用65535，这个值比较大， 造成很多连接积压在队列里， 由于队列处理的比较慢， 导致连接超时， 超时的连接由于还没有accept， 因此不会处理请求，也不会被close， 造成CLOSE_WAIT状态，这就是我们从tcpdump中看到的现象。 等到accept获取到一个连接， 实际是获取到一个CLOSE_WAIT状态的连接， 等write调用向连接写数据时，自然会报错。 这就同时完美解释了tcpdump跟strace看似矛盾的结果。


  1. 解释

这里有必要解释下， TCP连接为什么会积压在队列里， 要理解这个问题， 需要先理解linux 对TCP 三次握手的一些具体实现。


我们知道， 在server端，监听一个端口， 调用socket,bind 最后调用listen：

int listen(intsockfd, int backlog);

listen的第二个参数叫做backlog， 用来设置连接队列的大小。实际Linux 维护两个队列， 一个是在接收到SYN后，此时没有完成三次握手， 处于半连接状态，存放到SYNqueue，  另一个是三次握手完成后， 成功建立连接，存放到acceptqueue，等待应用调用accept 来消费队列。这里的backlog就是用来设置accept queue（旧版内核用来设置SYN queue，详细请man listen）的大小。


TCP 传输跟系统调用实际是一个异步的过程， 系统通过队列来保存最新的TCP状态或数据。也就是说，TCP三次握手由内核来完成， 跟应用层是否调用accept无关， 内核将完成三次握手的socket 放到acceptqueue中，应用调用accept 时，从accept queue中获取连接。那么，如果backlog 非常大，而我又不及时调用accept 来消费队列，则连接就被积压到accept queue中了。


同样， 在三次握手完成后， 客户端就可以发送数据了， 数据由内核接收， 并保存在TCP 的buffer中， 而此时应用（PHP）可能还没有调用accept。


因此， 如果积压在accept queue中的连接如果已经被对方close， 应用仍然可以accept到这个连接， 也可以调用read 读取buffer中的数据， 但是，当调用write 时， 则报错：Broken pipe。


  1. 疑问

Backlog过高的猜想，可以解释当前的故障现象， 但仍然有很多疑问需要解决

  1. accept queue 是如果慢慢积压的？流量突增还是后端变慢？

  2. 连接积压后， PHP获取到的都是close掉的连接，不需要返回响应，应该会快速失败，那么消费accept queue的速度应该大大提高，最终将close掉的连接都快速消费掉，系统应该会恢复正常，但现实情况下负载却持续很高，并且没有恢复， 为什么？

  3. Nginx 做反向代理时， 可以自动摘掉失效的后端， 后端摘掉后，不再有新的请求路由过来，从而accept queue得以消费，慢慢恢复正常，但从nginx日志看， nginx 根本就没摘掉后端，为什么？

  4. 上下文切换cswch/s 为什么突升？


  1. 解答

  2. 1 对于acceptqueue 如何慢慢积压，暂时我还没有确凿的证据，不过可以通过日志和配置做一些推想。首先从PHP slow log看， PHP进程偶尔会出现fastcgi_finish_request 执行慢的情况， 时间超过2s， 此时accept queue 必然会有增长， 另外， 我们的PHP-FPM 配置了max_request=102400也就是处理102400 个请求后， fpm的worker进程会自动退出， fpm重新派生（respawn）worker进程，如果负载比较均衡的话，所有子进程应该几乎同时退出(因为pm为static模式)，并且从PHP源码看，PHP没有对这个机制做任何优化，在这个过程中 accept queue也必然会积压。


6.2 PHP 进程为什么没有因为快速失败而快速消费队列呢， 这里从strace 可以找到答案， 我们看下， PHP在write brokenpipe后，到底又做了什么。通过对比正常php进程跟异常php进程的strace结果，我发现异常PHP进程在写log前调用flock，耗时比较多：

1403674085.279482 flock(4, LOCK_EX)     = 0

1403674085.668528 write(4, "1\t1\t1403674085\xx\t11"..., 76) =76

1403674085.668565flock(4, LOCK_UN)     = 0


1403674085.668– 1403674085.279大约相差400ms， 而正常的PHP进程：


1403680571.144737flock(4, LOCK_EX)     = 0 <0.000014>

1403680571.144784write(4, "1\t1\t1403680571\xx\t11"..., 74) = 74 <0.000014>

1403680571.144833flock(4, LOCK_UN)     = 0<0.000017>

几乎没有耗费时间！ 因此我们可以想到， 当大多进程都快速失败时， 他们会同时去写日志， 由于我们的日志程序在写日志前都调用flock加锁， 导致PHP进程由于争夺锁而堵塞， 因此丧失了快速消费acceptqueue的机会！


关于flock， 我查了下PHP 手册， 其实一般情况下， 用append方式打开文件写日志时，是不需要加锁的， 因为其本身为原子操作，具体参考：http://cn2.php.net/manual/en/function.fwrite.php

Note:

If handle was fopen()ed in appendmode, fwrite()s are atomic(unless the size of string exceeds the filesystem's block size, onsome platforms, and as long as the file is on a local filesystem). That is,there is no need to flock() a resourcebefore calling fwrite();all of the data will be written without interruption.

6.3 Nginx 为什么没有摘掉后端？

通过分析nginx 的配置文件， 我发现目前有两个vhost， 其中一个是 A.cn， 其中关于fastcgi的超时fastcgi_read_timeout设置为100ms，可见这个时间是很容易造成超时的。另外一个vhost 配置了一系列域名，我这里就用B.cn来代替了，其中没有配置fastcgi 相关的超时。会采用默认值60s。


关于upstream 的配置是这样的：

server10.121.96.206:9000 max_fails=10 fail_timeout=5m;

表示， 如果有10次连续失败， 则摘掉后端5分钟， 5分钟后再尝试恢复后端。从这里看到， nginx 是配置了摘除后端的功能的。我统计了故障时段以及故障以前的请求分布，发现故障时段请求数并没有减少，说明nginx根本没有摘除后端。


我确认了相应版本nginx的源码， 没有发现摘除功能的任何bug， 于是试图分析nginx access_log， 发现大量请求的返回状态码为499。499 代表nginx发现客户端主动断开了连接， 这时nginx会断开到upstream的连接并记录日志，状态码记为499，一般出现在客户端设置有超时的情况下。问题于是出现了，对于client 主动断开连接， nginx 认为是客户端放弃了请求，并不是后端失败，因此不会计入失败次数，也就不会摘掉后端了。


Vhost A.cn 中设置fastcgi_read_timeout 为100ms，而客户端的超时一般不会是毫秒级别的，因此这个vhost 如果超时不可能是客户端超时，而是fastcgi超时，因此记录状态码应该为504，而不是499，那么499 必定大多是由vhost B.cn 导致的，B.cn 没有设置fastcgi_read_timeout ，默认为60s，因此很可能导致客户端超时。


从请求分布的统计结果来看， 故障前后每分钟请求数基本没有变化， 那么说明不能摘掉后端的vhost B.cn的请求占比例应该很大，从而导致可以摘掉后端的vhost A.cn 就算摘除了后端对请求数影响也不大。为了验证这个推论， 我统计了accesslog， 发现 B.cn 占了大约85%的流量。因此推论正确。


Nginx 由于客户端超时，不认为是后端失败， 从而没有摘掉后端，丧失了故障恢复的机会。


6.4 上下文切换cswch/s 为什么突升？

这个问题， 我没有确切答案， 不过可以合理推论， 几百进程同事flock等待锁， 当锁可用时， 几百进程会同时唤醒，但只有一个进程能够得到锁，其他进程在分配到时间片后，由于无法获取锁，只能放弃时间片再次wait，从而导致上下文切换飙升，但CPU使用率却升高的不明显。当然这只是推论，大家如果有什么想法，欢迎一起讨论。(Update: 2014-07-04, 经试验，频繁flock确实会是cswch/s上升)


解决

从以上分析看出， 问题虽然是由于backlog 从128 变为65535 引起， 但问题实际涉及从客户端，nginx，到php等多个方面，而这多个方面都有问题，综合导致了这次故障。

因此我建议多方面同时调整，彻底解决问题：

  1. nginx 设置超时， 至少小于客户端的超时时间， 否则摘除机制形同虚设。

  2. backlog 设置为合理值， 可以参考排队论， 通过qps，以及处理时间实际可以确定队列大小， 比如qps为1000，限时在100ms内返回， 则队列大小设置为1000*0.1=100比较合适， 否则我明明知道等我处理到这个连接，其早就超时了， 还要将连接放到队列，肯定是不合理的。

  3. 写日志时，去掉flock，因为append 方式打开文件， fwrite是原子操作（除非要写的字符串大于文件系统的block，一般block是4k，应该不会超过吧？）。


验证

上线PHP5.5.13，配置listen.backlog为128，等待1到2周，观察故障是否会再次出现。预期：不出现

上线PHP5.3.8， 配置listen.backlog 为65535，等待1到2周， 观察故障能否出现。预期：出现

上线PHP5.3.28，配置listen.backlog为128，等待1到2周，观察故障能否出现。预期：不出现


之所以验证PHP 5.3.28是因为据业务反映，以前测试时，这个版本也有问题，但5.3.28 默认backlog是128，如果存在问题，则上面的结论就完全错了。因此我要求重新验证一下。


验证结果(2014-07-31)

经过一个月的线上验证，PHP 5.5.13自从listen.backlog 改为128后，表现正常。PHP5.3.28也没有问题。这两个都符合预期，但listen.backlog 为65535的PHP5.3.8出乎意料，没有出现异常。


对于backlog积压的真正原因，我这边已经确定，是凌晨0点切割日志导致。切割日志脚本在mv完日志后, 发送

SIGUSR1信号给php-fpmmaster进程，php-fpm会reopen日志文件，并通知所有worker进程退出。这一瞬间会造成一定的连接队列的积压，不过这不是主要原因，主要原因是随后脚本查找并删除2天前的日志文件，由于文件较多，估计应该几百G，造成iowait偏高。导致连接队列的积压。最高积压可达到上千。


Tue Jul 29 00:00:50CST 2014 3: CE60790A:2328 00000000:0000 0A 00000000:000004FC00:00000000 00000000 0 0 4205691288 1 ffff8101b2c7e6c0 3000 0 0 2 -1


统计数据从/proc/net/tcp获取， 并每秒打印一次， 可以看到00:00:50这一刻， 连接队列的积压达到0x000004FC， 转化为10进制，也就是1276个。


另外，我采集了凌晨日志切割时负载的相关数据，listen.backlog 为65535 的PHP5.3.8 负载最高达100以上。连接积压最多达1000以上。而listen.backlog 为128 的PHP5.5.13, 由于限制了连接队列，其最大积压为129（128+1），最高负载在70左右。负载之所以仍然很高，这是由删除日志导致。

总结

系统负载居高不下，无法恢复，与多个因素有关，首先，删除日志，导致iowait过高，堵塞了PHP进程，从而无法及时消费连接队列，由于listen.backlog 设置为65535时，连接几乎一直积压在连接队列，由于nginx设置的100ms超时，导致大量连接超时关闭。大量PHP进程由于无法返回响应，时间都集中在写日志方面，引起flock惊群。此时，就算iowait恢复正常，由于flock过慢，nginx 无法及时摘除后端，系统也无法恢复正常了。


从以上信息可以，各影响因素有一个发生改变，可能都不会导致系统负载居高不下的问题：

  1. Nginx A.cn 调整100ms，如果时间够长，则连接队列的socket不会被close掉，就不会导致大量PHP进程集中写日志。

  2. 减小listen.backlog，如果backlog足够小，新的连接会直接拒掉，连接队列就不会积压太多连接。就算都被close掉，也不会有太多影响。

  3. 写日志去掉flock，这样避免flock惊群，等iowait恢复时，系统负载也就恢复了。

  4. Nginx B.cn 配置合理的超时时间，这样在后端超时时，可以自动摘除有问题的后端，使后端有机会恢复负载。

  5. 避免iowait过高，这样就不会拖慢PHP，不会积压连接，也就不存在负载过高的问题了。

转自：http://mp.weixin.qq.com/s?__biz=MjM5NzUwNDA5MA==&mid=200667929&idx=1&sn=67cada895ac100115fded319b6b23a21&key=c9a93e01d964b270352d389085430573fed32dd997889ff6b9d57cecdb8bc83d088765301ff810c60a924da13d4412e7&ascene=1&uin=MjkxNjI0MTEwNQ%3D%3D&devicetype=webwx&version=70000001&pass_ticket=AlEFlenm81sNuX1SOiF1RUn0Us%2BnJgP%2FdrXlngavXlxXRxshLziNHsbmdmpWDPPX