Nginx+PHP(laravel) 环境 499 错误码排查过程小记

转载

码农编程进阶笔记 2021-06-23 13:18:03

文章标签 php 文章分类 PHP 后端开发

前言

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

过程

0x01

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

首先，这个问题百度谷歌应该都能搜到。
其次，我还是回答一下

499, client has closed connection

代表客户端主动断开了连接，一般是服务端处理时间太长了，客户端等不了就断开了
还有一种情况就是有人攻击，故意消耗服务端资源。

在nginx源码中，499对应的定义是 “client has closed connection”。这很有可能是因为服务器端处理的时间过长，客户端“不耐烦”了。要解决此问题，就需要在程序上面做些优化了。

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

但某一时间段内全部请求均为返回 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 左右。

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