Node.js 调试指南

 主页   资讯   文章   代码   电子书 

上一小节讲解了 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

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

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

有以下三点需要解释:

  1. 定义了一个全局 Map 来存储函数的调用关系,在适当的地方(下面会讲到)将当前请求的 ctx 存储到 Map 中,key 是 asyncId。
  2. 每个异步资源在初始化时,会尝试通过 asyncId 向上寻找祖先的 value 是否是 ctx(koa 应用中每个请求的 ctx),如果有,则直接将 value 设置为 ctx,否则将 value 设置为调用者的 asyncId(即 triggerAsyncId)。
  3. 在 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) {
    ...
  }
}

有以下两点需要解释:

  1. logger 函数传入的第 1 个参数 ctx,之前是每个请求的 ctx,现在可能是当前执行上下文的 this,所以先将 ctx 赋值给 originalContext,然后通过 await fn.call(originalContext) 让函数在执行时有正确的上下文。
  2. 如果传入的 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 参考链接

  • https://nodejs.org/dist/latest-v8.x/docs/api/async_hooks.html
  • https://zhuanlan.zhihu.com/p/27394440
  • https://www.jianshu.com/p/4a568dac41ed

上一节:6.1 koa-await-breakpoint

下一节:6.3 ELK