前一段时间开始搞优化后端 API 性能的事，发现根本无从下手， Kibana 中虽然有记一些简陋且零散的日志，但也瞅不出啥眉目来。总结了下是日志太少了，所以决定先搞搞日志的事，目标是记录 API 请求相关的日志，找出哪个接口慢，最好具体到哪个函数慢。
记日志必然要涉及日志打点，怎么做日志打点是个问题。如果直接在代码中插入日志打点代码不仅侵入性强而且工作量大，也不够灵活，于是考虑如何做智能的自动打点。我们石墨后端使用的 bay 框架（基于 Koa@1 二次开发，基本上你可以认为就是用的 Koa ）， controller 里用了大量的 yield ，所以考虑是不是可以在 yield 表达式前后打点，调研了下觉得可以用 esprima 和 escodegen 做。
奋战几天， koa-yield-breakpoint 诞生了。
koa-yield-breakpoint
koa-yield-breakpoint 就是一个在 controllers 或者 routes 里的 yield 表达式前后打点的工具，不用插入一行日志打点代码，只需要在引入的时候配置一下，可以记录每个请求到来时 yield 表达式前后的现场，如：
1 、 yield 表达式所在的行列号（ filename ） 2 、 yield 表达式是执行的第几步（ step ） 3 、 yield 表达式字符串形式（ fn ） 4 、执行 yield 表达式所花费的时间（ take ） 5 、执行 yield 表达式的结果（ result ） 6 、 yield 表达式当时的现场（ this ），通过 this 你也可以添加自定义字段
原理：
1 、重载 Module.prototype.-compile ，相当于 hack 了 require ，如果发现是 require 了配置里指定的的文件，则进行下一步，否则返回原始代码内容，相关源代码如下：
shimmer.wrap(Module.prototype, '_compile', function (__compile) {
return function koaBreakpointCompile(content, filename) {
if (!_.includes(filenames, filename)) {
return __compile.call(this, content, filename);
}
...
};
});
2 、用 esprima 解析代码，生成 AST 。如：
'use strict';
const Mongolass = require('mongolass');
const mongolass = new Mongolass();
mongolass.connect('mongodb://localhost:27017/test');
exports.getUsers = function* getUsers() {
yield mongolass.model('users').create({
name: 'xx',
age: 18
});
const users = yield mongolass.model('users').find();
this.body = users;
};
会生成如下 AST ：
Program {
type: 'Program',
body:
[ Directive {
type: 'ExpressionStatement',
expression:
Literal {
type: 'Literal',
value: 'use strict',
raw: '\'use strict\'',
loc: { start: { line: 1, column: 0 }, end: { line: 1, column: 12 } } },
directive: 'use strict',
loc: { start: { line: 1, column: 0 }, end: { line: 1, column: 13 } } },
VariableDeclaration {
type: 'VariableDeclaration',
declarations:
[ VariableDeclarator {
type: 'VariableDeclarator',
id:
Identifier {
type: 'Identifier',
name: 'Mongolass',
loc: { start: { line: 3, column: 6 }, end: { line: 3, column: 15 } } },
init:
CallExpression {
type: 'CallExpression',
callee:
Identifier {
type: 'Identifier',
name: 'require',
loc: { start: { line: 3, column: 18 }, end: { line: 3, column: 25 } } },
arguments:
[ Literal {
type: 'Literal',
value: 'mongolass',
raw: '\'mongolass\'',
loc: { start: { line: 3, column: 26 }, end: { line: 3, column: 37 } } } ],
loc: { start: { line: 3, column: 18 }, end: { line: 3, column: 38 } } },
loc: { start: { line: 3, column: 6 }, end: { line: 3, column: 38 } } } ],
kind: 'const',
loc: { start: { line: 3, column: 0 }, end: { line: 3, column: 39 } } },
VariableDeclaration {
type: 'VariableDeclaration',
declarations:
[ VariableDeclarator {
type: 'VariableDeclarator',
id:
Identifier {
type: 'Identifier',
name: 'mongolass',
loc: { start: { line: 4, column: 6 }, end: { line: 4, column: 15 } } },
init:
NewExpression {
type: 'NewExpression',
callee:
Identifier {
type: 'Identifier',
name: 'Mongolass',
loc: { start: { line: 4, column: 22 }, end: { line: 4, column: 31 } } },
arguments: [],
loc: { start: { line: 4, column: 18 }, end: { line: 4, column: 33 } } },
loc: { start: { line: 4, column: 6 }, end: { line: 4, column: 33 } } } ],
kind: 'const',
loc: { start: { line: 4, column: 0 }, end: { line: 4, column: 34 } } },
ExpressionStatement {
type: 'ExpressionStatement',
expression:
CallExpression {
type: 'CallExpression',
callee:
StaticMemberExpression {
type: 'MemberExpression',
computed: false,
object:
Identifier {
type: 'Identifier',
name: 'mongolass',
loc: { start: { line: 5, column: 0 }, end: { line: 5, column: 9 } } },
property:
Identifier {
type: 'Identifier',
name: 'connect',
loc: { start: { line: 5, column: 10 }, end: { line: 5, column: 17 } } },
loc: { start: { line: 5, column: 0 }, end: { line: 5, column: 17 } } },
arguments:
[ Literal {
type: 'Literal',
value: 'mongodb://localhost:27017/test',
raw: '\'mongodb://localhost:27017/test\'',
loc: { start: { line: 5, column: 18 }, end: { line: 5, column: 50 } } } ],
loc: { start: { line: 5, column: 0 }, end: { line: 5, column: 51 } } },
loc: { start: { line: 5, column: 0 }, end: { line: 5, column: 52 } } },
ExpressionStatement {
type: 'ExpressionStatement',
expression:
AssignmentExpression {
type: 'AssignmentExpression',
operator: '=',
left:
StaticMemberExpression {
type: 'MemberExpression',
computed: false,
object:
Identifier {
type: 'Identifier',
name: 'exports',
loc: { start: { line: 7, column: 0 }, end: { line: 7, column: 7 } } },
property:
Identifier {
type: 'Identifier',
name: 'getUsers',
loc: { start: { line: 7, column: 8 }, end: { line: 7, column: 16 } } },
loc: { start: { line: 7, column: 0 }, end: { line: 7, column: 16 } } },
right:
FunctionExpression {
type: 'FunctionExpression',
id:
Identifier {
type: 'Identifier',
name: 'getUsers',
loc: { start: { line: 7, column: 29 }, end: { line: 7, column: 37 } } },
params: [],
body:
BlockStatement {
type: 'BlockStatement',
body:
[ ExpressionStatement {
type: 'ExpressionStatement',
expression:
YieldExpression {
type: 'YieldExpression',
argument:
CallExpression {
type: 'CallExpression',
callee:
StaticMemberExpression {
type: 'MemberExpression',
computed: false,
object: [Object],
property: [Object],
loc: [Object] },
arguments: [ [Object] ],
loc: { start: [Object], end: [Object] } },
delegate: false,
loc: { start: { line: 8, column: 2 }, end: { line: 11, column: 4 } } },
loc: { start: { line: 8, column: 2 }, end: { line: 11, column: 5 } } },
VariableDeclaration {
type: 'VariableDeclaration',
declarations:
[ VariableDeclarator {
type: 'VariableDeclarator',
id: Identifier { type: 'Identifier', name: 'users', loc: [Object] },
init:
YieldExpression {
type: 'YieldExpression',
argument: [Object],
delegate: false,
loc: [Object] },
loc: { start: [Object], end: [Object] } } ],
kind: 'const',
loc:
{ start: { line: 13, column: 2 },
end: { line: 13, column: 54 } } },
ExpressionStatement {
type: 'ExpressionStatement',
expression:
AssignmentExpression {
type: 'AssignmentExpression',
operator: '=',
left:
StaticMemberExpression {
type: 'MemberExpression',
computed: false,
object: ThisExpression { type: 'ThisExpression', loc: [Object] },
property: Identifier { type: 'Identifier', name: 'body', loc: [Object] },
loc: { start: [Object], end: [Object] } },
right:
Identifier {
type: 'Identifier',
name: 'users',
loc: { start: [Object], end: [Object] } },
loc:
{ start: { line: 14, column: 2 },
end: { line: 14, column: 19 } } },
loc:
{ start: { line: 14, column: 2 },
end: { line: 14, column: 20 } } } ],
loc: { start: { line: 7, column: 40 }, end: { line: 15, column: 1 } } },
generator: true,
expression: false,
loc: { start: { line: 7, column: 19 }, end: { line: 15, column: 1 } } },
loc: { start: { line: 7, column: 0 }, end: { line: 15, column: 1 } } },
loc: { start: { line: 7, column: 0 }, end: { line: 15, column: 2 } } } ],
sourceType: 'script',
loc: { start: { line: 1, column: 0 }, end: { line: 15, column: 2 } } }
相关源代码如下：
let parsedCodes;
try {
parsedCodes = esprima.parse(content, { loc: true });
} catch (e) {
console.error('cannot parse file: %s', filename);
console.error(e.stack);
process.exit(1);
}
3 、遍历找到 YieldExpression 节点，进行以下包装后生成 AST 替换掉原来的节点。
global.logger(
this,
function*(){
return YieldExpression
},
YieldExpressionString,
filename
);
相关源代码如下：
findYieldAndWrapLogger(parsedCodes);
try {
content = escodegen.generate(parsedCodes, {
format: { indent: { style: ' ' } },
sourceMap: filename,
sourceMapWithCode: true
});
} catch (e) {
console.error('cannot generate code for file: %s', filename);
console.error(e.stack);
process.exit(1);
}
debug('file %s regenerate codes:\n%s', filename, content.code);
findYieldAndWrapLogger 作用就是遍历 AST 将 YieldExpression 替换成用日志函数包裹后新的 YieldExpression 的 AST 。
<未完待续> ----敬请期待 Koa 请求日志打点工具（下篇）
这是一个专为移动设备优化的页面（即为了让你能够在 Google 搜索结果里秒开这个页面），如果你希望参与 V2EX 社区的讨论，你可以继续到 V2EX 上打开本讨论主题的完整版本。
V2EX 是创意工作者们的社区，是一个分享自己正在做的有趣事物、交流想法，可以遇见新朋友甚至新机会的地方。
V2EX is a community of developers, designers and creative people.