如何在Node.js中测量请求从进入事件循环到开始处理的耗时

核心实现逻辑 #

要统计所有请求从进入事件队列到开始处理的时间差，核心是在请求刚触达服务时记录第一个时间戳，再将实际处理逻辑推入事件队列的下一个调度周期，两个时间戳的差值就是请求的队列等待耗时。

具体实现步骤 #

• 第一步：在HTTP请求回调触发的第一时间记录入口时间戳，该时间可以近似为请求进入事件队列的时间
• 第二步：用setImmediate()包裹实际业务处理逻辑，setImmediate的回调会在当前事件循环周期清空后执行，此时计算的时间差就是队列等待耗时
• 第三步：将所有请求的耗时存入统计数组，全量请求处理完成后可输出平均、分位、最大/最小等统计指标

代码示例 #

const http = require('http');

// 存储全量请求的等待耗时数据
const latencyRecords = [];
// 测试场景的总请求量，可按需调整
const TOTAL_REQUESTS = 1000;
let handledCount = 0;

const server = http.createServer((req, res) => {
  // 记录请求刚触达服务的时间戳，需要更高精度可替换为process.hrtime()
  const entryTime = Date.now();

  setImmediate(() => {
    // 计算队列等待耗时
    const waitLatency = Date.now() - entryTime;
    latencyRecords.push(waitLatency);
    handledCount++;

    // 此处写实际的业务处理逻辑
    res.writeHead(200);
    res.end('请求处理完成');

    // 全量请求处理完成后输出统计结果
    if (handledCount === TOTAL_REQUESTS) {
      console.log('===== 事件队列等待耗时统计结果 =====');
      console.log(`平均耗时：${(latencyRecords.reduce((sum, val) => sum + val, 0) / latencyRecords.length).toFixed(2)}ms`);
      console.log(`最大耗时：${Math.max(...latencyRecords)}ms`);
      console.log(`最小耗时：${Math.min(...latencyRecords)}ms`);
    }
  });
});

server.listen(3000);

补充说明 #

• 如果使用Express、Koa等框架，可以把这段逻辑封装为全局中间件，无需修改业务代码即可实现全量统计
• 该方案不会遗漏任何请求，完全满足全量统计的需求

原理补充：Node.js的HTTP请求完成内核层握手后会先进入事件队列等待调度，当前执行栈清空后才会触发HTTP请求回调，因此回调第一时间的时间戳和setImmediate回调的时间差，就是请求在事件队列中的真实等待时长。

内容的提问来源于stack exchange，提问作者Higor Duarte de Oliveira