日志篇 - Async Hooks - 《Node.js 调试指南》

6.2.1 Async Hooks
6.2.2 改造 koa-await-breakpoint
6.2.3 参考链接

上一小节讲解了 koa-await-breakpoint 的用法，但 koa-await-breakpoint 仍然有一个很大的缺憾，即无法记录除 routes/controllers 外的函数的执行时间（因为获取不到当前请求的 ctx）。举个通俗的例子：在一个路由的 controller 里面调用了 A ，A 调用了其他文件的 B ，B 又调用了其他文件的 C…这是非常常见的用法，但之前使用 koa-await-breakpoint 只能获取 A 的执行时间，无法获取 B 和 C 的执行时间。

根本原因在于：无法知道函数之间的调用关系，即 B 不知道是 A 调用的它，即便知道也不知道是哪次请求到来时执行的 A 调用的它。

但是，node@8.1 引入了一个黑魔法——Async Hooks。

6.2.1 Async Hooks

我们先看看 async_hooks 是什么。Node.js 官网对 async_hooks 的介绍为：

The async_hooks module provides an API to register callbacks tracking the lifetime of asynchronous resources created inside a Node.js application.

一句话概括：async_hooks 用来追踪 Node.js 中异步资源的生命周期。

我们来看段测试代码：

const fs = require('fs')
const async_hooks = require('async_hooks')
async_hooks.createHook({
  init (asyncId, type, triggerAsyncId, resource) {
    fs.writeSync(1, `${type}(${asyncId}): trigger: ${triggerAsyncId}\n`)
  },
  destroy (asyncId) {
    fs.writeSync(1, `destroy: ${asyncId}\n`);
  }
}).enable()
async function A () {
  fs.writeSync(1, `A -> ${async_hooks.executionAsyncId()}\n`)
  setTimeout(() => {
    fs.writeSync(1, `A in setTimeout -> ${async_hooks.executionAsyncId()}\n`)
    B()
  })
}
async function B () {
  fs.writeSync(1, `B -> ${async_hooks.executionAsyncId()}\n`)
  process.nextTick(() => {
    fs.writeSync(1, `B in process.nextTick -> ${async_hooks.executionAsyncId()}\n`)
    C()
    C()
  })
}
function C () {
  fs.writeSync(1, `C -> ${async_hooks.executionAsyncId()}\n`)
  Promise.resolve().then(() => {
    fs.writeSync(1, `C in promise.then -> ${async_hooks.executionAsyncId()}\n`)
  })
}
fs.writeSync(1, `top level -> ${async_hooks.executionAsyncId()}\n`)
A()

async_hooks.createHook 可以注册 4 个方法来跟踪所有异步资源的初始化（init）、回调之前（before）、回调之后（after）、销毁后（destroy）事件，并通过调用 .enable() 启用，调用 .disable() 关闭。

这里我们只关心异步资源的初始化和销毁的事件，并使用 fs.writeSync(1, msg) 打印到标准输出，writeSync 的第 1 个参数接收文件描述符，1 表示标准输出。为什么不使用 console.log 呢？因为 console.log 是一个异步操作，如果在 init、before、after 和 destroy 事件处理函数中出现，就会导致无限循环，同理也不能使用任何其他的异步操作。

运行该程序，打印如下：

top level -> 1
PROMISE(6): trigger: 1
A -> 1
Timeout(7): trigger: 1
TIMERWRAP(8): trigger: 1
A in setTimeout -> 7
PROMISE(9): trigger: 7
B -> 7
TickObject(10): trigger: 7
B in process.nextTick -> 10
C -> 10
PROMISE(11): trigger: 10
PROMISE(12): trigger: 11
C -> 10
PROMISE(13): trigger: 10
PROMISE(14): trigger: 13
C in promise.then -> 12
C in promise.then -> 14
destroy: 7
destroy: 10
destroy: 8

这段程序的打印结果包含了很多信息，下面逐一进行解释：

为了实现对异步资源的跟踪，Node.js 对每一个函数（不论异步还是同步）提供了一个 async scope，我们可以通过调用 async_hooks.executionAsyncId() 来获取函数当前的 async scope 的 id（称为 asyncId），通过调用 async_hooks.triggerAsyncId() 来获取当前函数调用者的 asyncId。
异步资源在创建时触发 init 事件函数，init 函数中的第 1 个参数代表该异步资源的 asyncId，type 表示异步资源的类型（例如 TCPWRAP、PROMISE、Timeout、Immediate、TickObject 等等），triggerAsyncId 表示该异步资源的调用者的 asyncId。异步资源在销毁时触发 destroy 事件函数，该函数只接收一个参数，即该异步资源的 asyncId。
函数调用关系明确。我们通过上面的打印结果可以很容易地看出（从下往上看）：C（asyncId: 10）被 B（asyncId: 7）调用，B（asyncId: 7）被 A（asyncId: 1）调用。而且 C 的 promise.then 里面的 asyncId（值为 12/14）也可以通过 12/14 -> 11/13 -> 10 定位到 C 的 asyncId（值为 10）。
同步函数每次调用的 asyncId 都一样，如上所示，C 调用了两次，都打印了 C -> 10，与调用方的作用域的 asyncId 一致，即如上所示打印的 B in process.nextTick -> 10。异步函数每次调用的 asyncId 都不一样，即如上所示打印的 C in promise.then -> 12 和 C in promise.then -> 14。
最外层作用域的 asyncId 总是 1，每个异步资源在创建时 asyncId 全局递增。

上面 5 条结论非常重要。接下来我们看看如何使用 async_hooks 改造 koa-await-breakpoint。

6.2.2 改造 koa-await-breakpoint

我们通过前面的结论已经知道，使用 async_hooks 时可以通过 asyncId 串起函数的调用关系，但是如何将这些函数的调用链与 koa 接收的每个请求关联起来呢?

首先，定义一个全局 Map，存储函数的调用关系：

const async_hooks = require('async_hooks')
const asyncIdMap = new Map()
async_hooks.createHook({
  init (asyncId, type, triggerAsyncId) {
    const ctx = getCtx(triggerAsyncId)
    if (ctx) {
      asyncIdMap.set(asyncId, ctx)
    } else {
      asyncIdMap.set(asyncId, triggerAsyncId)
    }
  },
  destroy (asyncId) {
    asyncIdMap.delete(asyncId)
  }
}).enable()
function getCtx (asyncId) {
  if (!asyncId) {
    return
  }
  if (typeof asyncId === 'object' && asyncId.app) {
    return asyncId
  }
  return getCtx(asyncIdMap.get(asyncId))
}

有以下三点需要解释：

定义了一个全局 Map 来存储函数的调用关系，在适当的地方（下面会讲到）将当前请求的 ctx 存储到 Map 中，key 是 asyncId。
每个异步资源在初始化时，会尝试通过 asyncId 向上寻找祖先的 value 是否是 ctx（koa 应用中每个请求的 ctx），如果有，则直接将 value 设置为 ctx，否则将 value 设置为调用者的 asyncId（即 triggerAsyncId）。
在 destroy 事件函数里直接删除调用关系，保证了不会引起内存泄漏，即杜绝引用了 ctx 但没有释放的情况。

然后，修改 global[loggerName] 如下：

global[loggerName] = async function (ctx, fn, fnStr, filename) {
  const originalContext = ctx
  let requestId = _getRequestId()
  const asyncId = async_hooks.executionAsyncId()
  if (!requestId) {
    const _ctx = getCtx(asyncId)
    if (_ctx) {
      ctx = _ctx
      requestId = _getRequestId()
    }
  } else {
    asyncIdMap.set(asyncId, ctx)
  }
  if (requestId) {
    _logger('beforeAwait')
  }
  const result = await fn.call(originalContext)
  if (requestId) {
    _logger('afterAwait', result)
  }
  return result
  function _getRequestId () {
    return ctx && ctx.app && _.get(ctx, requestIdPath)
  }
  function _logger (type, result) {
    ...
  }
}

有以下两点需要解释：

logger 函数传入的第 1 个参数 ctx，之前是每个请求的 ctx，现在可能是当前执行上下文的 this，所以先将 ctx 赋值给 originalContext，然后通过 await fn.call(originalContext) 让函数在执行时有正确的上下文。
如果传入的 ctx 是来自请求的 ctx 且能拿到 requestId，那么将当前 asyncId 和 ctx 写入 Map，如果不是来自请求的 ctx，则尝试从 Map 里向上寻找祖先的 value 是否是 ctx，如果找到，则覆盖当前的 ctx 并拿到 requestId。

至此，koa-await-breakpoint 全部改造完毕。接下来我们通过一个例子验证下升级后的 koa-await-breakpoint：

app.js

const koaAwaitBreakpoint = require('koa-await-breakpoint')({
  files: ['./routes/*.js']
})
const Paloma = require('paloma')
const app = new Paloma()
app.use(koaAwaitBreakpoint)
app.route({ method: 'POST', path: '/users', controller: require('./routes/user').createUser })
app.listen(3000)

routes/users.js

const Mongolass = require('mongolass')
const mongolass = new Mongolass('mongodb://localhost:27017/test')
const User = mongolass.model('User')
const Post = mongolass.model('Post')
const Comment = mongolass.model('Comment')
exports.createUser = async function (ctx) {
  const name = ctx.query.name || 'default'
  const age = +ctx.query.age || 18
  await createUser(name, age)
  ctx.status = 204
}
async function createUser (name, age) {
  const user = (await User.create({
    name,
    age
  })).ops[0]
  await createPost(user)
}
async function createPost (user) {
  const post = (await Post.create({
    uid: user._id,
    title: 'post',
    content: 'post'
  })).ops[0]
  await createComment(user, post)
}
async function createComment (user, post) {
  await Comment.create({
    userId: user._id,
    postId: post._id,
    content: 'comment'
  })
}

这段代码的意思是：在访问创建用户接口时，调用 createUser，createUser 里面又调用了 createPost，createPost 里面又调用了 createComment。运行：

$ curl -XPOST localhost:3000/users

打印如下：

{ type: 'start',
  step: 1,
  take: 0 ... }
{ type: 'beforeAwait',
  step: 2,
  fn: 'createUser(name, age)',
  take: 1 ... }
{ type: 'beforeAwait',
  step: 3,
  fn: 'User.create(...)',
  take: 1 ... }
{ type: 'afterAwait',
  step: 4,
  fn: 'User.create(...)',
  take: 36 ... }
{ type: 'beforeAwait',
  step: 5,
  fn: 'createPost(user)',
  take: 1 ... }
{ type: 'beforeAwait',
  step: 6,
  fn: 'Post.create(...)',
  take: 0 ... }
{ type: 'afterAwait',
  step: 7,
  fn: 'Post.create(...)',
  take: 3 ... }
{ type: 'beforeAwait',
  step: 8,
  fn: 'createComment(user, post)',
  take: 1 ... }
{ type: 'beforeAwait',
  step: 9,
  fn: 'Comment.create(...)',
  take: 0 ... }
{ type: 'afterAwait',
  step: 10,
  fn: 'Comment.create(...)',
  take: 1 ... }
{ type: 'afterAwait',
  step: 11,
  fn: 'createComment(user, post)',
  take: 1 ... }
{ type: 'afterAwait',
  step: 12,
  fn: 'createPost(user)',
  take: 6 ... }
{ type: 'afterAwait',
  step: 13,
  fn: 'createUser(name, age)',
  take: 44 ... }
{ type: 'end',
  step: 14,
  take: 0 ... }

至此，一个全链路、无侵入、强大的日志打点工具就完成了。

注意：使用 async_hooks 在目前有较严重的性能损耗，见 https://github.com/bmeurer/async-hooks-performance-impact，请慎重在生产环境中使用。

6.2.3 参考链接

上一节：6.1 koa-await-breakpoint

下一节：6.3 ELK