前言

某公安项目过程中,在内网服务器部署 WNMP 环境,运行 Laravel 框架代码,后查看日志发现某一时刻突然所有请求 499,并持续一段时间,遂排查原因。

过程

0x01

经搜索得知: 哪些情况下会使 Nginx 返回 HTTP CODE 499?

即:「客户端主动关闭连接」

但某一时间段内全部请求均为返回 499,这显然不是所有客户端主动意识上的「关闭」,可能是因为客户端等待超时,自动关闭连接;加上 499 的时间段内包含部分 502,让我不得不怀疑:

PHP 进程「死」了。

0x02

这里的死,不一定是进程结束,也有可能是僵尸,或是陷入死循环,一直在执行某个脚本……

若是逐个检查代码时间来不及(以先解决问题为重),遂排查: Nginx+FastCGI 到底是谁影响超时时间

以及: PHP-max_execution_time 与 fpm.request_terminate_timeout 介绍

0x03

经过上面的调整,大约一周后再次维护服务器。发现情况有所改善—— 499 错误已经由某一时段大量、集中出现变为偶尔发生,且只出现在某几个特定 URI 请求上。

我决定对这几个 URI 对应的接口控制器代码进行检查。由于系统开发时间紧张,代码质量并不高,怀疑是否是程序内有 BUG。

首先查看代码执行时间,约为 1900 ms 左右,简直太慢!经过仔细检查,发现几个严重问题:

  • 查出某表「全部结果」,再「遍历」结果集,查询每条记录「多个字段」的关联模型
  • 未执行 php artisan optimize
  • 未关闭 debug 模式
  • 未调整 log_level

其中,后几条或许无关紧要,但第一条绝对是致命的。

假设一种常见的模型关联场景:

某作者有多篇文章,每篇文章又有多条评论、赞。

由此,若是采用类似:

posts = posts::where('user_id', 1);
foreach(posts as post){
    likes = post->likes;
    comments = post->comments;
}

在 Laravel 框架内使用类似如上的方式查询,假设作者的文章数为 n,每篇文章关联的模型有 2 个(likes & comments),则执行此控制器,对于数据库的时间复杂度为:O(n*2+1),需要执行如此大量的 SQL 语句!这在后端设计中应该是需要完全避免的,理想情况的时间复杂度应该是 O(n),n 为常量,不受数据规模的影响。

于是修改代码,过程不再详叙,参见 Laravel 官方文档,或: Laravel 学习笔记之模型关联预加载

经过修改,在 Chrome 开发者工具内查看请求 Timing,缩短为原来时间的一半,800ms 左右。

(但此值仍然不够理想,受到视图渲染、操作系统等原因的影响,后期继续优化,不属于本文讨论范围。)

后记

对于部分接口,请求一次需要执行几百条 SQL;那么,回到最开始的问题:

某次请求后,突然引发大量 499。究其根本原因,是否在于因代码的不严谨,引起的 MySQL 死锁呢?

值得研讨。