[转载] PHP升级致使系统负载太高问题分析

原文：http://chuansongme.com/n/797172

背景

据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抓包看下网络到底发生了什么。

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 复用端口新建链接……如此循环往复。

突破

那么问题是， 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看似矛盾的结果。

解释

这里有必要解释下， 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。

疑问

• Backlog 太高的猜测，能够解释当前的故障现象， 但仍然有不少疑问须要解决

• accept queue 是若是慢慢积压的？流量突增仍是后端变慢？

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

• Nginx 作反向代理时， 能够自动摘掉失效的后端， 后端摘掉后，再也不有新的请求路由过来，从而accept queue得以消费，慢慢恢复正常，但从nginx日志看， nginx 根本就没摘掉后端，为何？
• 上下文切换cswch/s 为何突升？

解答

6.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等多个方面，而这多个方面都有问题，综合致使了此次故障。

所以我建议多方面同时调整，完全解决问题：

• nginx 设置超时， 至少小于客户端的超时时间， 不然摘除机制形同虚设。
• backlog 设置为合理值， 能够参考排队论， 经过qps，以及处理时间实际能够肯定队列大小， 好比qps为1000，限时在100ms内返回， 则队列大小设置为1000*0.1=100比较合适， 不然我明明知道等我处理到这个链接，其早就超时了， 还要将链接放到队列，确定是不合理的。
• 写日志时，去掉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 没法及时摘除后端，系统也没法恢复正常了。

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

• Nginx A.cn 调整100ms，若是时间够长，则链接队列的socket不会被close掉，就不会致使大量PHP进程集中写日志。
• 减少listen.backlog，若是backlog足够小，新的链接会直接拒掉，链接队列就不会积压太多链接。就算都被close掉，也不会有太多影响。
• 写日志去掉flock，这样避免flock惊群，等iowait恢复时，系统负载也就恢复了。
• Nginx B.cn 配置合理的超时时间，这样在后端超时时，能够自动摘除有问题的后端，使后端有机会恢复负载。
• 避免iowait太高，这样就不会拖慢PHP，不会积压链接，也就不存在负载太高的问题了。