周一上午十点来钟,客户在群里发了个截图:浏览器里一片白,中间一行 502 Bad Gateway。配一句"又打不开了,刷新几下能好,过一会儿又这样"。

我第一反应是问:什么时候开始的?客户说上周就这样了,断断续续,一直以为是他们自己网络的事,这两天变频繁了才报上来。

先上服务器看 nginx。systemctl status nginx 是活的,error.log 拉最后几十行,干干净净,连个 warning 都没有。我心想那简单,reload 一下试试,反正不花钱。reload 完我自己 curl 了一下,通了。跟客户说再观察。

结果不到四十分钟,群里又炸了:又 502 了。

这时候我才正经起来。先怀疑是不是防火墙把 php-fpm 的端口挡了。这台机器是台老机器,CentOS 7.9,上面跑的 php-fpm 走的是 unix socket,不走端口——我脑子一抽还是去查了 iptables,当然啥也没有。现在回头看这一步纯属瞎转悠,但在当时,每一步都显得特别合理。

又怀疑是 socket 权限问题。网上那些"502 就 chmod 777 /run/php-fpm"的帖子我居然也信了,真去 chmod 777 了。后来同事知道了,说我这操作够他笑一年。确实够蠢,权限问题的话 error.log 会写 Permission denied,不会像现在这样啥都不写。

真正有用的线索是等 502 再犯的时候抓到的。error.log 里出现了一行:

connect() to unix:/var/run/php-fpm/www.sock failed (11: Resource temporarily unavailable) while connecting to upstream

Resource temporarily unavailable,翻译过来就是 php-fpm 忙不过来,队列满了,nginx 这边连接直接被拒。这就对上了:为什么 reload 一下就好——php-fpm 也跟着被 reload 了,占着的进程全被清掉,当然好。等跑一阵,进程又被占满,接着 502。

那问题就变成:谁把 php-fpm 的进程占满了?

我先干了个笨事:把 pm.max_children 从 20 调到 50,重启。好了一个下午,傍晚又犯。这说明不是容量不够的问题——是有人把进程长期占住不放。

第二天我开了 php-fpm 的 slow log,request_slowlog_timeout 设了 10 秒。这玩意儿平时我是不开的,怕日志量太大,这次特殊情况。第二天中午一查,抓到了:有个导出接口,平均执行时间 180 多秒,最长一条 246 秒。一个导出接口跑四分钟,这不就是占着茅坑不拉屎吗。

找开发问这个接口干嘛的。开发说就是导出一批订单,循环里逐条调第三方物流查询 API。我让他把响应时间打出来看看,好家伙,单条查询平均 30 秒——对方限流了,每次请求都等超时才返回。一次导出两千多条订单,就算不全部超时,也够把 php-fpm 那点进程全耗死的。

处理倒不复杂。开发那边改成先批量查、查不到的部分再逐条补,加了本地缓存,同一个单号五分钟内不重复查。改完那个接口从 180 多秒降到 4 秒上下。我这边把 pm.max_children 调回 30,slow log 留着没关,打算观察一周再说。

第三天开始,群里再没出现过 502 的截图。

后来想想,这事的坑不在技术,在于"重启一下就好"这个假象。它让你觉得问题不严重,于是每次都用最省事的办法糊弄过去,糊弄了整整一个礼拜。现在我再遇到这种"重启就好、过会儿再犯"的毛病,第一件事就是开 slow log 或者看 upstream 的超时时间,先找谁把进程占住了,而不是急着调大容量。调大容量只是把问题往后推,该排队还是排队。