思路一：查看请求数量
我的第一反应是查看整点时的 API 请求数量。通过日志统计，请求数量很大，但是在服务器承受范围内。换句话说，服务器处理这些请求绰绰有余。因为，我们有 9 台服务器。每台服务器配置如下：
CPU：16核。
内存：16 GB
硬盘：SSD。
PHP-FPM 进程数：400
均衡负载采用的是阿里云的 SLB。
数据库采用了阿里云的 RDS 高配版。查看其负载也属于低消状态。
根据理论值，我们 9 台服务器最少能承受的请求数量等于：9 * 400 = 3600。
当然要达到这个并发数量级别，有可能数据库会出现性能问题。
思路二：查看 MySQL 慢查询日志
通过对 MySQL 慢查询日志进行分析，几乎没有出现。或者说，出现的 MySQL 慢查询日志跟平常的差不多。都属于一些管理后台复杂查询类别的慢查询。
如思路一中所说：MySQL 服务器负载很小。所以，排除了 MySQL 服务器的问题。
思路三：查看 PHP-FPM 慢请求
对 PHP-FPM 熟悉的同学，都应该知道在 PHP-FPM 配置文件当中有如下两个配置：
request_slowlog_timeout = 1
slowlog = log/slow.log
request_slowlog_timeout 的作用是告诉 PHP-FPM，凡是请到开始到响应结束之间消耗的时间超过 1 秒就认为慢请求。就将造成慢请求的日志记录在 slowlog 指定的文件当中。
结果，通过这个日志我们发现了大量的慢请求。慢请求的关键日志如下:
[27-Nov-2018 14:50:48] [pool www] pid 19708
script_filename = xxxxxxx/public/index.php
[0x00007fb12cc48688] file_put_contents() xxxxxxx/library/winer/Log.php:98
[0x00007fb12cc48138] store() xxxxxxx/apps/controllers/Index.php:54
[0x00007fff0b8f8780] indexAction() unknown:0
[0x00007fb12cc47998] run() xxxxxxx/public/index.php:13
上面的信息我隐去了与环境相关的路径前缀。通过慢请求日志可以看出，我们在调用 file_put_contents 位置造成了慢请求的产生。这个位置是我们写日志造成的。
奇怪的是。我们写日志使用了阿里云的云盘。根据购买云盘的配置为 5000 IOPS/s。也不会出现瓶颈。于是，我查看了我们这个位置的 PHP 代码。
file_put_contents($logPath, $logCtx, FILE_APPEND|LOCK_EX);
可以看到，我们加了一个 LOCK_EX 参数。就是说写入日志的时候排它性，独占写锁。之所以当初要增加这个，是因为并发写的时候会造成日志位置错乱，两次日志信息互相包含。导致不能按照完整的顺序写入。
于是，我暂时把这个参数去掉之后，发现服务器 TCP 连接数瞬间下降到合理水平。基本可以确定是这里的问题了。于是，我把写日志更改为了异步。在异步里面进行独占写。
以上就是我排查本次问题的思路步骤。谢谢！
猜你喜欢: