499问题查询解决

本文记录了我从遇到 499 问题，到解决的全过程。

如果有小伙伴比较急，需要知道问题可能出现在哪里，请直接看 解决思路 一栏

随着公司的发展，系统也越来越健全。近期使用了阿里云的 sls 服务来分析 nginx 系统日志，并设立了告警功能。

各种平时注意不到的异常情况发生了。

系统环境

经典的 LNMP

什么是 499

解释是：client has closed connection

这很有可能是因为服务器端处理的时间过长，客户端“不耐烦”了。

解决思路

先考虑程序是否有问题，定位某个接口，做详细分析。

再考虑服务是否有问题，是不是 MySQL 的连接数量太少、是不是 PHP-FPM 的进程数量不够。

最后考虑用户行为。

第一次499处理

当我看到运维同事报过来的第一个 499 数据的时候，我感觉有点莫名。

之前没有处理过相应的问题，第一次拿到这个问题，还有点棘手。

大致分析了一下，大部分的请求响应都还算可以，在 0.5s 以内，部分情况会超过 1s。

由于占比不大，所以最终也没有得出什么结论。

也就不了了之了。

解决日志上报失败得来的惊喜

一些信息

我们部分接口会放在响应之前上报相关日志，因为是同步的，所以上报的时间会算在接口响应中。

问题

领导找到，说商品列表的响应速度太慢了，让查一下原因。

定位问题

既然是响应慢，那我得知道慢在什么地方，才好解决问题。

于是用了很暴力的解决方式，就是在我认为可能出现问题的节点放入调试时间，最终通过相减得到每个环节需要的时间。

最终发现，除了上报，其他所有的相应都很快。

然后查了一下上报日志，最近果断没有相关的日志。

再看到有其他接口的日志，略微比较一下之后，发现了问题。

为了好分析线上报的一些问题，我将响应数据一起上报了，不知道是怎么回事，现在上报数据一大就会出现问题。

所以就去除了上报数据，上报成功，接口响应也提升了。

499变少了

由于接口响应变快了，相关的 499 也减少了。

收到了告警邮件

运维同事偷偷的配置了告警邮件，并写上了我，然后，被轰炸了。

再上征途

一些信息

我们会在一些平台投放广告，前人用了 talking data 的服务(简称 TD)，TD 对接第三方平台，TD 再通知我们。

奇怪的现象

我分析了一下日志。

从分布上，激活的接口(TD 通知的接口)报 499 的概率非常之高。

从响应时长上，激活的接口最高达到了 60秒。

然后，又针对激活的接口做仔细分析，最终发现，在报 499 的时候，激活接口的响应时间会有个 增长 的趋势。

猜测

现在问题出现了，那是什么原因造成的呢？

1、猜测一

猜测：因为激活数量一直在递增，目前已经达到千万级，可能是没用到索引。

实际：有用到索引

2、猜测二

猜测：因为激活数据会产生插入更新，索引排序时间过长，导致阻塞。

实际：最终发现不是，这个没有验证。

3、猜测三

猜测：MySQL连接数量不足

实际：远远没达到(有监控可以直接看出，没有监控的话，只能根据数据分析了)

4、猜测四

猜测：PHP-FPM 进程不足，导致阻塞

实际：巅峰情况下只使用了 1/3

分析PHP慢日志

在所有猜测都不是的情况下，最终看了一下线上的 PHP 慢日志(这个一般不会开启)。

有了不一样的的发现。

在激活接口出现 499 的时间段内，经常出现 session_start 的慢日志(配置的是超过 3s 会出现慢日志)。

那么是为什么呢？

我将其归为 session_start 的时候，需要文件写权限(默认的，没有更改)，而当出现并发的时候，这个时候争夺文件锁的时候，发生了阻塞，导致后续请求阻塞了，最终超时。

想起之前本地环境也在 session_start 时出现过问题，就有了大致的解决方案。

1、不启动 session。事实上是可以的，因为是单纯的接口，不需要使用 session。

2、设置 session_save_handler 为 redis 和 memcached，他们在高并发下的能力更强。

最终，我关闭了 session，观察了一段时间，没有告警了。

一些思考

或许有些小伙伴已经想到了，既然是接口，理论上 session 是不会重复的。

这里有一个信息，talking data 使用的是 Apache-HttpClient/4.5.2。查了一下，它本身会处理 set-cookie 的操作，下一次请求就会带上 cookie。所以就尴尬了，由于同一个 PHPSESSID 的高并发，所以文件锁阻塞了。

最后

感觉自己解决问题的时候，先想的是不是别人的问题造成的，这个想法和处理方式是有问题的。

应该是先从本身分析，当本身没问题了，再去找外围的问题，会更好的解决问题。