Trace 链路追踪

Http 慢日志只能展示出根据开发者设置的 apdex 值计算得出的不能容忍的请求的一些基本信息,包括 host、url、status code、耗时以及发生的时间等信息。

但是绝大部分时候,这些信息不能帮助开发者定位到实际的请求耗时操作,所以提供了这样的一个慢链路追踪模块,旨在帮助开发者能以更清晰的方式解决慢 HTTP 请求问题。

此功能已经正式上线,欢迎大家使用并提出反馈意见。

用法

I. 升级 @alicloud/agenthub

首先执行如下命令重新安装 @alicloud/agenthub 模块来升级最新的 agentx 依赖:

npm install @alicloud/agenthub

需要确认下上一步全局安装的 agenthub 依赖的 agentx 版本 >=1.10.1,才能正常使用 tracing 功能。

安装完成后,按照原来的方式重启下 agenthub 即可生效。

II. 使用 @alicloud/opentracing 埋点

目前需要开发者使用 @alicloud/opentracing 这个模块在整个 HTTP 请求的耗时操作(一般是异步调用)前后进行手动埋点来串联起整个调用链路,下面是此模块的用法。

1. 安装

npm install @alicloud/opentracing

2. 使用

公共类:Tracer(name[, option][, reporter]):

a. 参数:

  • name String - tracer 的名称

  • option Object - 可选

    • limit Number - 每分钟限制记录落盘的数据条数限制,防止大量异常的情况下大量日志写入文件造成磁盘溢出

    • logger Object - 日志句柄,最小需要实现 info、log、warn 和 error 方法,默认采用 console

  • reporter Object - 自定义发送方法,需要实现 report 方法,入参为 span

b. 成员方法:startSpan(spanName[, option])

  • spanName String - span 的名称,用来标记此 span 下的异步调用

  • option Object - 可选

    • childOf Object - 传入当前 span 的父级 span 实例

  • 返回值 Object - 返回内置的类 Span 的实例

内置类:Span

a. 成员方法:setTag(tag, value)

  • tag String - Tag 名称,可以自定义,一般从 opentracing.Tags 中获取(里面定义了常见的 host、url、statusCode 等链路信息 Key)

  • value String - Tag 名称对应的值

b. 成员方法:log(key, value)

  • key String - 自定义的日志键

  • value String - 自定义的日志值

c. 成员方法:finish(req)

  • req Object - http 请求的 request 对象

完整例子

下面是一个给 express 应用中间件埋点的使用完整样例,模拟了并发的异步耗时调用,和顺序的异步耗时调用:

注意: 有效的 root span(即能在控制台正常看到的慢链路)中的 tags 信息必须包含 HTTP_METHODHTTP_URLHTTP_STATUS_CODE,否则会被服务端过滤掉!

'use strict';
const express = require('express');
const app = express();
const opentracing = require('@alicloud/opentracing');
const tracer = new opentracing.Tracer('测试链路');
// 模拟耗时的异步操作
function delay(time, req) {
  let child = tracer.startSpan('子模块 1: 随机并发延迟', { childOf: req.parentSpan });
  child.setTag('timeout', time);
  child.log({ state: 'timer1' });
  return new Promise((resolve, reject) => {
    setTimeout(() => {
      resolve();
      child.finish(req);
    }, time);
  });
}
// 在所有中间件之前,开启一个根 span,记录下 hostname、method、url,以及收到 end 事件后的
app.use(function (req, res, next) {
  req.parentSpan = tracer.startSpan('根模块');
  req.parentSpan.setTag(opentracing.Tags.PEER_HOSTNAME, req.hostname);
  req.parentSpan.setTag(opentracing.Tags.HTTP_METHOD, req.method.toUpperCase());
  req.parentSpan.setTag(opentracing.Tags.HTTP_URL, req.url);
  next();
  res.once('finish', () => {
    req.parentSpan.setTag(opentracing.Tags.HTTP_STATUS_CODE, res.statusCode);
    req.parentSpan.finish(req);
  });
});
// 模拟并发的耗时异步操作
app.use(function (req, res, next) {
  Promise.all([
    delay(Math.random() * 10 * 1000, req),
    delay(Math.random() * 10 * 1000, req)
  ]).then(() => next());
});
// 继续模拟一个顺序的 3s 耗时异步操作
app.use(function (req, res, next) {
  let child = tracer.startSpan('子模块 2: 延迟 3s', { childOf: req.parentSpan });
  child.setTag('timeout', '3s');
  child.log({ state: 'timer2' });
  // 3s call
  setTimeout(() => {
    child.finish(req);
    next()
  }, 3000);
});
// 响应页面
app.get('*', function (req, res) {
  res.send('Hello Node.js Performance Platform!');
});
app.listen(3000);

在浏览器请求 http://localhost:3000/delay, 等待约 1min 后,可以在控制台的相应 Tab 页看到:

点击 请求信息 栏下面对应的字符串或者长条可以看到开发者自行记录的当前请求详情,比如例子中在随机延迟中分别用 tag 和 log 记录了当前延迟 ms 数和定时器名称,那么点开 子模块1 对应的请求信息栏中的长条后可以看到如下内容: