上一小节讲解了 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。
我们先看看 async_hooks 是什么。Node.js 官网对 async_hooks 的介绍为：
The
async_hooksmodule 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这段程序的打印结果包含了很多信息，下面逐一进行解释：
async_hooks.executionAsyncId() 来获取函数当前的 async scope 的 id（称为 asyncId），通过调用 async_hooks.triggerAsyncId() 来获取当前函数调用者的 asyncId。上面 5 条结论非常重要。接下来我们看看如何使用 async_hooks 改造 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))
}有以下三点需要解释：
然后，修改 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) {
...
}
}有以下两点需要解释：
await fn.call(originalContext) 让函数在执行时有正确的上下文。至此，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.3 ELK