用 microtime(true) 手动打点最准：在中间件 handle() 开头和结尾记录时间差，注意异常提前退出、嵌套调用及 Swoole 下的 time drift 问题。
中间件耗时怎么测：用 microtime(true) 手动打点最准
ThinkPHP 自带的中间件执行流程不暴露各环节耗时，Trace 工具默认只统计控制器和数据库，中间件被“吞掉”了。想定位是哪个中间件拖慢接口，得自己加计时点。
在中间件 handle() 开头记一次时间，结尾再记一次，差值就是真实耗时：
public function handle($request, \Closure $next)
{
$start = microtime(true);
$response = $next($request);
$cost = round((microtime(true) - $start) * 1000, 2);
// 记日志或写入 trace（见下节）
\think\facade\Log::info("Middleware {$this->name} cost: {$cost}ms");
return $response;
}- 别用
time()，精度不够，毫秒级差异全抹平 - 注意：如果中间件里有
return提前退出（比如鉴权失败），要确保每个出口都打点，否则漏算 - 多个中间件共用一个日志通道时，建议加
$this->name或类名做区分，不然日志里分不清谁干的
Trace 工具为啥没显示中间件耗时：默认关闭 + 不支持自动注入
Trace 是 ThinkPHP 的调试面板，但它对中间件的耗时采集是“选择性失明”的——不是 bug，是设计如此。它只监听 AppInit、HttpRun、RouteCheck 等固定节点，中间件不在监听白名单里。
- 开启
trace并不能自动补全中间件数据，配置'trace' => ['type' => 'html']没用 - 想让中间件出现在 Trace 面板里，必须手动调用
\think\facade\Debug::remark()打标记点 - 推荐在中间件开头写
\think\facade\Debug::remark("middleware.{$this->name}.start")，结尾写\think\facade\Debug::remark("middleware.{$this->name}.end") - 然后在 Trace 面板「性能分析」页签里就能看到这些自定义标记的时间差
快速筛查慢接口：用日志 + 时间阈值过滤，别等 Trace 页面加载
开发环境开着 Trace 是方便，但线上不敢开，而且 Trace 页面本身也慢。真要排查问题，靠日志+阈值更直接可靠。
立即学习“PHP免费学习笔记（深入）”；
- 在全局中间件（如
AppInit或自定义入口中间件）里统一埋点，记录请求 URL、开始时间、结束时间、状态码 - 加一行判断：
if ($cost > 500) { \think\facade\Log::notice("Slow request: {$url}, cost: {$cost}ms"); } - 注意：不要把所有请求都记 info 日志，否则磁盘爆得比接口还快；只记 warn / notice 级别且超阈值的
- 配合 Linux 命令快速抓取：
grep "Slow request" runtime/log/*.log | sort -k6nr | head -20（按耗时倒序取前 20）
常见踩坑点：中间件嵌套、异常跳过、Swoole 下的 time drift
你以为中间件耗时好测？这几个地方一不留神就错得离谱。
- 中间件 A 调用了中间件 B（比如用
$next链式调用），但你在 B 里又写了microtime，结果 A 和 B 的耗时互相包含，日志里出现“B 耗时 800ms，A 总耗时 600ms”这种逻辑矛盾 - 中间件里抛出异常并被捕获（比如 try-catch 后返回 401），
$next($request)根本没执行，但你只在结尾打点，导致耗时恒为 0 - Swoole 模式下，
microtime(true)在长连接中可能因进程复用产生微小漂移，建议改用hrtime(true)（PHP 7.3+），或至少加个gc_collect_cycles()减少干扰 - 别信框架文档里“中间件执行很快”的说法——加密解密、远程配置拉取、JWT 验证这些操作一旦塞进中间件，轻松破 300ms
中间件不是黑盒，但也不是透明玻璃。耗时数据得自己凿出来，而且每次加新中间件，都要重验一遍打点逻辑是否覆盖所有路径。
