Heroku托管的Laravel API出现间歇性响应慢、请求超时及慢执行报错

实际运行场景说明 #

本地环境运行一切正常，线上环境大部分请求可正常返回，但会间歇性出现请求响应缓慢甚至超时的情况。

当出现慢响应时，会记录如下慢执行日志：

2021-04-07T14:07:08.267681+00:00 app[web.1]: [07-Apr-2021 14:07:08] WARNING: [pool www] child 145, script '/app/public/index.php' (request: "GET /index.php") executing too slow (3.062416 sec), logging
2021-04-07T14:07:08.268185+00:00 app[web.1]: 
2021-04-07T14:07:08.268269+00:00 app[web.1]: [07-Apr-2021 14:07:08]  [pool www] pid 145
2021-04-07T14:07:08.268346+00:00 app[web.1]: script_filename = /app/public/index.php
2021-04-07T14:07:08.268538+00:00 app[web.1]: [0x00007f4cb9618040] execute() /app/vendor/doctrine/dbal/lib/Doctrine/DBAL/Driver/PDOStatement.php:112
2021-04-07T14:07:08.268729+00:00 app[web.1]: [0x00007f4cb9617fc0] execute() /app/vendor/laravel/framework/src/Illuminate/Database/Connection.php:343
2021-04-07T14:07:08.269002+00:00 app[web.1]: [0x00007f4cb9617f20] Illuminate\Database\{closure}() /app/vendor/laravel/framework/src/Illuminate/Database/Connection.php:671
2021-04-07T14:07:08.269207+00:00 app[web.1]: [0x00007f4cb9617e60] runQueryCallback() /app/vendor/laravel/framework/src/Illuminate/Database/Connection.php:638
2021-04-07T14:07:08.269390+00:00 app[web.1]: [0x00007f4cb9617da0] run() /app/vendor/laravel/framework/src/Illuminate/Database/Connection.php:346
2021-04-07T14:07:08.269589+00:00 app[web.1]: [0x00007f4cb9617d10] select() /app/vendor/laravel/framework/src/Illuminate/Database/Query/Builder.php:2313
2021-04-07T14:07:08.269788+00:00 app[web.1]: [0x00007f4cb9617ca0] runSelect() /app/vendor/laravel/framework/src/Illuminate/Database/Query/Builder.php:2301
2021-04-07T14:07:08.270038+00:00 app[web.1]: [0x00007f4cb9617bd0] Illuminate\Database\Query\{closure}() /app/vendor/laravel/framework/src/Illuminate/Database/Query/Builder.php:2796
2021-04-07T14:07:08.270249+00:00 app[web.1]: [0x00007f4cb9617b30] onceWithColumns() /app/vendor/laravel/framework/src/Illuminate/Database/Query/Builder.php:2302
2021-04-07T14:07:08.270443+00:00 app[web.1]: [0x00007f4cb9617a50] get() /app/vendor/laravel/framework/src/Illuminate/Database/Eloquent/Builder.php:588
2021-04-07T14:07:08.270650+00:00 app[web.1]: [0x00007f4cb9617920] getModels() /app/vendor/laravel/framework/src/Illuminate/Database/Eloquent/Builder.php:572
2021-04-07T14:07:08.270837+00:00 app[web.1]: [0x00007f4cb9617820] get() /app/vendor/laravel/framework/src/Illuminate/Database/Eloquent/Model.php:477
2021-04-07T14:07:08.270978+00:00 app[web.1]: [0x00007f4cb96177a0] all() /app/vendor/tcg/voyager/routes/voyager.php:39
2021-04-07T14:07:08.271163+00:00 app[web.1]: [0x00007f4cb96176d0] {closure}() /app/vendor/laravel/framework/src/Illuminate/Routing/Router.php:423
2021-04-07T14:07:08.271362+00:00 app[web.1]: [0x00007f4cb9617650] loadRoutes() /app/vendor/laravel/framework/src/Illuminate/Routing/Router.php:382
2021-04-07T14:07:08.271552+00:00 app[web.1]: [0x00007f4cb96175b0] group() /app/vendor/laravel/framework/src/Illuminate/Support/Facades/Facade.php:261
2021-04-07T14:07:08.271709+00:00 app[web.1]: [0x00007f4cb9617500] __callStatic() /app/vendor/tcg/voyager/routes/voyager.php:133
2021-04-07T14:07:08.271894+00:00 app[web.1]: [0x00007f4cb9617470] {closure}() /app/vendor/laravel/framework/src/Illuminate/Routing/Router.php:423
2021-04-07T14:07:08.272080+00:00 app[web.1]: [0x00007f4cb96173f0] loadRoutes() /app/vendor/laravel/framework/src/Illuminate/Routing/Router.php:382
2021-04-07T14:07:08.272276+00:00 app[web.1]: [0x00007f4cb9617350] group() /app/vendor/laravel/framework/src/Illuminate/Support/Facades/Facade.php:261
2021-04-07T14:07:09.811958+00:00 app[web.1]: 99.99.99.99 - - [07/Apr/2021:14:07:05 +0000] "GET /api/v1/mentors HTTP/1.1" 200 7278 "-" "PostmanRuntime/7.26.10
2021-04-07T14:07:09.819006+00:00 heroku[router]: at=info method=GET path="/api/v1/mentors" host=xxxxxxxxxxxxxx.herokuapp.com request_id=17d1f729-e3a2-41dc-8c92-f0b917623b74 fwd="999.999.999.99" dyno=web.1 connect=1ms service=4615ms status=200 bytes=7586 protocol=https

其余时段请求响应迅速，耗时仅数百毫秒，对应日志如下：

2021-04-07T14:15:37.182510+00:00 app[web.1]: 99.99.99.99 - - [07/Apr/2021:14:15:36 +0000] "GET /api/v1/mentors HTTP/1.1" 200 7278 "-" "PostmanRuntime/7.26.10
2021-04-07T14:15:37.183580+00:00 heroku[router]: at=info method=GET path="/api/v1/mentors" host=xxxxxxxxxxxxxxxxxxx.herokuapp.com request_id=0b8ccc3f-8e3f-44bf-91c0-71ef6d245ad2 fwd="999.999.999.999" dyno=web.1 connect=0ms service=300ms status=200 bytes=7586 protocol=https
2021-04-07T14:15:47.637135+00:00 app[web.1]: 99.99.99.99 - - [07/Apr/2021:14:15:47 +0000] "GET /api/v1/mentors HTTP/1.1" 200 7278 "-" "PostmanRuntime/7.26.10
2021-04-07T14:15:47.638294+00:00 heroku[router]: at=info method=GET path="/api/v1/mentors" host=xxxxxxxxxxxxxxxxxxx.herokuapp.com request_id=8b415575-eb68-4fd4-87df-bca90f5fbf26 fwd="999.999.999.999" dyno=web.1 connect=0ms service=454ms status=200 bytes=7586 protocol=https
2021-04-07T14:15:51.658485+00:00 heroku[router]: at=info method=GET path="/api/v1/mentors" host=xxxxxxxxxxxxxxxxxxx.herokuapp.com request_id=c91c02d4-5141-4002-81aa-05507c0ea3f9 fwd="999.999.999.999" dyno=web.1 connect=1ms service=729ms status=200 bytes=7586 protocol=https
2021-04-07T14:15:51.655872+00:00 app[web.1]: 99.99.99.99 - - [07/Apr/2021:14:15:50 +0000] "GET /api/v1/mentors HTTP/1.1" 200 7278 "-" "PostmanRuntime/7.26.10

已完成的排查动作 #

• 最初判断异常来自多表关联查询的性能问题，后续测试发现即便单表基础查询也会出现相同的响应波动
• 调整 configureRateLimiting 配置值，将阈值从60调高至10000，未对问题产生任何改善

可选排查方向 #

• 结合慢日志堆栈定位：当前慢执行的最终卡点落在 Voyager 路由加载阶段触发的模型全表查询，可检查公开API请求的启动流程中，是否存在无差别执行Voyager相关路由加载、全表数据查询的逻辑，将这类后台专属逻辑和公开API请求做隔离
• 验证Heroku dyno休眠机制影响：基础套餐的dyno在1小时无请求后会自动进入休眠状态，唤醒后的首个请求需要重新初始化PHP-FPM worker、加载全部Laravel框架文件，会出现数秒级的响应耗时，后续同进程处理的请求则会回到正常速度，这种场景的耗时特征和日志表现完全匹配
• 排查数据库连接稳定性：慢日志的堆栈明确卡在DBAL语句执行阶段，可检查Heroku托管数据库的连接数是否达上限、是否存在空闲连接超时回收不及时的问题，这类连接层面的异常会偶发导致查询等待数秒，且不会复现固定的SQL性能问题
• 检查PHP-FPM进程回收配置：如果配置了pm.max_requests、pm.process_idle_timeout规则，当worker达到请求数上限时会自动重启，刚好落在重启窗口的请求会等待新worker初始化完成，表现为偶发的响应耗时波动
• 校验OPcache开启状态：如果线上环境未开启OPcache，每次请求都需要重新编译所有PHP文件，叠加Heroku容器偶发的磁盘IO波动，会放大不同请求间的耗时差

内容的提问来源于stack exchange，提问作者Chris WB