需对请求生命周期各阶段分段耗时采集:一、用内置Trace面板快速定位开发瓶颈;二、自定义中间件划分六阶段计时并写入日志;三、监听数据库事件统计SQL耗时分布;四、用Debug门面打点实现代码块级细粒度分析;五、注入X-Response-Time头并聚合分析P50/P90/P99。
如果您在ThinkPHP应用中观察到部分请求响应明显延迟,但无法判断耗时集中于框架启动、数据库查询、模板渲染还是业务逻辑环节,则需对请求生命周期各阶段进行分段耗时采集。以下是实现请求耗时分布统计分析的多种方法:
一、使用内置Trace调试面板(开发环境)
该方式依赖ThinkPHP调试模式,在HTML页面响应中自动注入可视化性能面板,展示SQL执行、文件加载、模板解析、内存占用及各阶段耗时占比,适用于快速定位开发阶段瓶颈。
1、确认config/app.
php
中
配置值为
。
2、确保请求头包含
,Postman或curl需手动添加此头,否则面板不渲染。
立即学习
“
PHP免费学习笔记(深入)
”;
3、访问任意HTML页面(非API接口),页面底部将显示Trace面板,其中
下方按模块展开各阶段时间分布,
SQL查询耗时
与
模板渲染耗时
可直接对比。
二、自定义中间件分段计时
通过在请求进入、控制器执行前后、响应发送前插入时间戳,可将整个生命周期划分为“框架初始化→路由匹配→中间件执行→控制器调用→视图渲染→响应发送”六个逻辑段,每段耗时独立记录并写入日志。
1、创建中间件
,在
方法开头记录
。
2、在
之后、
之前记录
。
3、在
调用前记录
。
4、构造结构化数组:
,并写入日志文件,字段名统一为
。
三、监听数据库事件捕获SQL耗时分布
数据库查询常是耗时主因,但单条SQL慢不等于整体慢;通过Db::listen()捕获所有查询及其毫秒级耗时,可统计慢SQL占比、平均查询耗时、最大单次查询耗时等分布指标。
1、在
或
中调用
。
PHP 8.5.5
PHP 8.5.5 是 PHP 8.5 分支的维护更新版本。该版本延续了“小步快跑”的迭代逻辑,通过深度错误修复、底层性能微调以及安全加固,旨在为开发者提供一个更健壮、更高效的运行环境。该版本严格遵守语义化版本规范,不包含破坏性变更。
下载
2、在回调内将
(单位:毫秒)与当前请求URI、时间戳一起存入临时数组
(仅调试环境启用)。
3、响应发送前遍历该数组,计算
、
、
、
,输出
慢查询数量/总查询数
及
慢查询平均耗时
。
四、利用Debug门面进行代码块级耗时打点
当怀疑某段循环、远程调用或文件处理逻辑拖慢响应时,可在控制器或模型中手动插入多个
标记,实现细粒度耗时切片,避免全局统计掩盖局部热点。
1、在业务逻辑起始处调用
。
2、在数据库查询后调用
,在HTTP请求返回后调用
,在循环结束时调用
。
3、依次调用
、
、
,结果以毫秒为单位返回,
各段差值即为对应环节真实耗时
。
五、注入X-Response-Time响应头并聚合分析
在每次响应头部写入总耗时,配合Nginx日志中的
字段,可交叉验证PHP层真实执行时间,并用于后续离线统计各URI的P50/P90/P99耗时分布。
1、在
中监听
事件。
2、从
获取起点,在事件回调内取当前
为终点,计算差值
。
3、调用
,确保该头出现在所有响应中。
4、配置Nginx日志格式,新增字段
,使用Logstash或awk脚本提取各URI的耗时列表,运行
获取分布值。
app_debugtrueAccept: text/html总耗时App\Middleware\TimingMiddleware.phphandle()$start = microtime(true)$request->filter()$response = $next($request)$afterRoute = microtime(true)$response->send()$beforeSend = microtime(true)['route' => $afterRoute - $start, 'controller' => $afterController - $afterRoute, 'view' => $beforeSend - $afterController]duration_msapp/bootstrap.phpApp\Providers\AppServiceProvider@register()Db::listen(function ($sql, $time, $explain) { ... })$time$_SESSION['db_times'][] = $timecountarray_summaxarray_filter($times, fn($t) => $t > 500)Debug::remark()Debug::remark('logic_start')Debug::remark('db_end')Debug::remark('http_end')Debug::remark('loop_end')Debug::time('logic_start', 'db_end')Debug::time('db_end', 'http_end')Debug::time('http_end', 'loop_end')$upstream_response_timeApp\Providers\AppServiceProvider@boot()think\ResponseSend$_SERVER['REQUEST_TIME_FLOAT']microtime(true)$cost$response->header('X-Response-Time', round($cost * 1000, 2) . 'ms')$sent_http_x_response_timesort -n | awk '{a[NR]=$1} END {print a[int(NR*0.5)], a[int(NR*0.9)], a[int(NR*0.99)]}'