溫馨提示×
您好，登錄后才能下訂單哦！
點擊 登錄注冊 即表示同意《億速云用戶服務條款》
您好，登錄后才能下訂單哦！
前一段時間開始搞優化后端 API 性能的事，發現根本無從下手，Kibana 中雖然有記一些簡陋且零散的日志，但也瞅不出啥眉目來。總結了下是日志太少了，所以決定先搞搞日志的事，目標是記錄 API 請求相關的日志，找出哪個接口慢，最好具體到哪個函數慢。
記日志必然要涉及日志打點，怎么做日志打點是個問題。如果直接在代碼中插入日志打點代碼不僅侵入性強而且工作量大，也不夠靈活，于是考慮如何做智能的自動打點。我們石墨后端使用的 bay 框架（基于 Koa@1 二次開發，基本上你可以認為就是用的 Koa），controller 里用了大量的 yield，所以考慮是不是可以在 yield 表達式前后打點，調研了下覺得可以用 esprima 和 escodegen 做。
奮戰幾天，koa-yield-breakpoint 誕生了。
koa-yield-breakpoint 就是一個在 controllers 或者 routes 里的 yield 表達式前后打點的工具，不用插入一行日志打點代碼，只需要在引入的時候配置一下，可以記錄每個請求到來時 yield 表達式前后的現場，如：
yield 表達式所在的行列號（filename）
yield 表達式是執行的第幾步（step）
yield 表達式字符串形式（fn）
執行 yield 表達式所花費的時間（take）
執行 yield 表達式的結果（result）
yield 表達式當時的現場（this），通過 this 你也可以添加自定義字段
原理：
重載 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);
}
...
};});用 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);}遍歷找到 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。
最后用 escodegen 將 AST 生成代碼（支持 soucemap，所以錯誤棧對應的行數是對的）。
核心：每個請求到來時，生成（項目中本來就有 requestId 的話，可通過配置指定）一個 requestId（uuid 類型）掛載到 this 上，這樣就可以通過 requestId 將日志串起來了。
特點：可以記錄每個請求的流程（甚至可以查到某個用戶某個時間段的請求），及每一次請求的每一步（step）的現場及返回值，方便調試或查 bug，當然只針對 yield 表達式。
app.js
'use strict';const koaYieldBreakpoint = require('koa-yield-breakpoint')({
files: ['./routes/*.js']});const koa = require('koa');const routes = require('./routes');const app = koa();app.use(koaYieldBreakpoint);routes(app);app.listen(3000, () => {
console.log('listening on 3000');});routes/index.js
'use strict';const route = require('koa-route');const users = require('./users');module.exports = function (app) {
app.use(route.get('/users', users.getUsers));};routes/users.js
'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;};運行：
DEBUG=koa-yield-breakpoint node app.js
終端打印如下：
example git:(master) DEBUG=koa-yield-breakpoint node app.jskoa-yield-breakpoint options: {"files":["./routes/*.js"],"nodir":true,"absolute":true,"filter":{"ctx":["state","params"],"request":["method","path","header","query","body"],"response":["status","body"]},"loggerName":"logger","requestIdPath":"requestId"} +0mskoa-yield-breakpoint matched files: ["/Users/nswbmw/node/koa-yield-breakpoint/example/routes/index.js","/Users/nswbmw/node/koa-yield-breakpoint/example/routes/users.js"] +9mskoa-yield-breakpoint file /Users/nswbmw/node/koa-yield-breakpoint/example/routes/index.js regenerate codes:'use strict';const route = require('koa-route');const users = require('./users');module.exports = function (app) {
app.use(route.get('/users', users.getUsers));}; +73mskoa-yield-breakpoint file /Users/nswbmw/node/koa-yield-breakpoint/example/routes/users.js regenerate codes:'use strict';const Mongolass = require('mongolass');const mongolass = new Mongolass();mongolass.connect('mongodb://localhost:27017/test');exports.getUsers = function* getUsers() {
yield global.logger(this, function* () {
return mongolass.model('users').create({
name: 'xx',
age: 18
});
}, 'mongolass.model(\'users\').create({\n name: \'xx\',\n age: 18\n})', '/Users/nswbmw/node/koa-yield-breakpoint/example/routes/users.js:8:2');
const users = yield global.logger(this, function* () {
return mongolass.model('users').find();
}, 'mongolass.model(\'users\').find()', '/Users/nswbmw/node/koa-yield-breakpoint/example/routes/users.js:13:16');
this.body = users;}; +15mslistening on 3000可以看出，routes/users.js 被替換成了：
'use strict';const Mongolass = require('mongolass');const mongolass = new Mongolass();mongolass.connect('mongodb://localhost:27017/test');exports.getUsers = function* getUsers() {
yield global.logger(this, function* () {
return mongolass.model('users').create({
name: 'xx',
age: 18
});
}, 'mongolass.model(\'users\').create({\n name: \'xx\',\n age: 18\n})', '/Users/nswbmw/node/koa-yield-breakpoint/example/routes/users.js:8:2');
const users = yield global.logger(this, function* () {
return mongolass.model('users').find();
}, 'mongolass.model(\'users\').find()', '/Users/nswbmw/node/koa-yield-breakpoint/example/routes/users.js:13:16');
this.body = users;};為什么要將 yield 表達式包裹成這樣呢？
global.logger(
this,
function*(){
return YieldExpression
},
YieldExpressionString,
filename);而不是：
global.logger(
this,
function(){
return YieldExpression
},
YieldExpressionString,
filename);或者：
global.logger( this, yield YieldExpression, YieldExpressionString, filename);
因為考慮到 YieldExpression 可能是以下情況導致 esprima 不能解析：
User.find(yield xxx)
User.find(http://this.xxx)
所以綜合考慮只能放到 GeneratorFunction 里，另外，不用：
global.logger(
this,
function*(){
return yield YieldExpression
},
YieldExpressionString,
filename
);是因為這樣會導致 esprima 解析死循環，所以去掉了里面的 yield，在 logger 里 yield。
訪問 localhost:3000/users，終端打印出:
{ requestId: 'dad593c0-c4a1-4640-a00e-9ba0349cfd2f',
timestamp: Wed Oct 26 2016 18:28:49 GMT+0800 (CST),
this:
{ state: {},
request:
{ method: 'GET',
path: '/users',
header: [Object],
query: [Object] },
response: { status: 404, body: undefined } },
type: 'start',
step: 1,
take: 0 }{ requestId: 'dad593c0-c4a1-4640-a00e-9ba0349cfd2f',
step: 2,
filename: '/Users/nswbmw/node/koa-yield-breakpoint/example/routes/users.js:8:2',
timestamp: Wed Oct 26 2016 18:28:49 GMT+0800 (CST),
this:
{ state: {},
request:
{ method: 'GET',
path: '/users',
header: [Object],
query: [Object] },
response: { status: 404, body: undefined } },
type: 'before',
fn: 'mongolass.model(\'users\').create({\n name: \'xx\',\n age: 18\n})',
result: undefined,
take: 1 }{ requestId: 'dad593c0-c4a1-4640-a00e-9ba0349cfd2f',
step: 3,
filename: '/Users/nswbmw/node/koa-yield-breakpoint/example/routes/users.js:8:2',
timestamp: Wed Oct 26 2016 18:28:49 GMT+0800 (CST),
this:
{ state: {},
request:
{ method: 'GET',
path: '/users',
header: [Object],
query: [Object] },
response: { status: 404, body: undefined } },
type: 'after',
fn: 'mongolass.model(\'users\').create({\n name: \'xx\',\n age: 18\n})',
result:
{ result: { ok: 1, n: 1 },
ops: [ [Object] ],
insertedCount: 1,
insertedIds: [ undefined, 5810856182d0eea2f12030fd ] },
take: 7 }{ requestId: 'dad593c0-c4a1-4640-a00e-9ba0349cfd2f',
step: 4,
filename: '/Users/nswbmw/node/koa-yield-breakpoint/example/routes/users.js:13:16',
timestamp: Wed Oct 26 2016 18:28:49 GMT+0800 (CST),
this:
{ state: {},
request:
{ method: 'GET',
path: '/users',
header: [Object],
query: [Object] },
response: { status: 404, body: undefined } },
type: 'before',
fn: 'mongolass.model(\'users\').find()',
result: undefined,
take: 1 }{ requestId: 'dad593c0-c4a1-4640-a00e-9ba0349cfd2f',
step: 5,
filename: '/Users/nswbmw/node/koa-yield-breakpoint/example/routes/users.js:13:16',
timestamp: Wed Oct 26 2016 18:28:49 GMT+0800 (CST),
this:
{ state: {},
request:
{ method: 'GET',
path: '/users',
header: [Object],
query: [Object] },
response: { status: 404, body: undefined } },
type: 'after',
fn: 'mongolass.model(\'users\').find()',
result: [ { _id: 5810856182d0eea2f12030fd, name: 'xx', age: 18 } ],
take: 4 }{ requestId: 'dad593c0-c4a1-4640-a00e-9ba0349cfd2f',
timestamp: Wed Oct 26 2016 18:28:49 GMT+0800 (CST),
this:
{ state: {},
request:
{ method: 'GET',
path: '/users',
header: [Object],
query: [Object] },
response: { status: 200, body: [Object] } },
type: 'end',
step: 6,
take: 1 }注意：type 是 ['start', 'beforeYield', 'afterYield', 'error', 'end'] 其中一種，take 單位是 ms。
start: 請求到來時第一次打點
beforeYield: 上一個 yieldExpression 之后到這一個 yieldExpression 之前
afterYield: 這個 yieldExpression 開始到結束
error: 錯誤日志，koa-yield-breakpoint 會記錄下來，然后再 throw 出去
end: 請求結束時打點
const koaYieldBreakpoint = require('koa-yield-breakpoint')({
files: ['./controllers/*.js', './middlewares/*.js'],
store: require('./lib/koa_yield_breakpoint_logstash'),
loggerName: '__logger',
requestIdPath: 'header.reqid',
yieldCondition: (filename, yieldExpression) => {
// yield next 不包裹 logger
if (yieldExpression === 'next') {
return {
wrapYield: false,
deep: false
};
}
if (yieldExpression.match(/^db\.sequelize\.transaction/)) {
return {
wrapYield: true,
deep: false
};
}
}});...app.use(koaYieldBreakpoint);koa-yield-breakpoint 主要用在 Koa 的 routes、controllers 或 middlewares 文件。co-yield-breakpoint 主要用來給普通 yield 表達式（如 lib 或 models 下的文件）打點（沒有 requestId，所以 log 是零散的，這里只用來計算平均耗時），實現原理跟 koa-yield-breakpoint 類似，這里不再贅述。
foo.js
'use strict';const co = require('co');const Mongolass = require('mongolass');const mongolass = new Mongolass();mongolass.connect('mongodb://localhost:27017/test');co(function* () {
yield mongolass.model('users').create({
name: 'xx',
age: 18
});
const users = yield mongolass.model('users').find();
console.log('users: %j', users);}).catch(e => console.error(e.stack));終端打印如下：
{
"filename": "/Users/nswbmw/node/co-yield-breakpoint/example/foo.js:9:2",
"timestamp": "2016-11-10T13:53:33.053Z",
"fn": "mongolass.model('users').create({\n name: 'xx',\n age: 18\n})",
"result": {
"result": {
"ok": 1,
"n": 1
},
"ops": [{
"name": "xx",
"age": 18,
"_id": "58247bdd3fb205dbad5418a0"
}],
"insertedCount": 1,
"insertedIds": [null, "58247bdd3fb205dbad5418a0"]
},
"take": 55}{
"filename": "/Users/nswbmw/node/co-yield-breakpoint/example/foo.js:14:16",
"timestamp": "2016-11-10T13:53:33.060Z",
"fn": "mongolass.model('users').find()",
"result": [{
"_id": "58247bdd3fb205dbad5418a0",
"name": "xx",
"age": 18
}],
"take": 7}users: [{
"_id": "58247bdd3fb205dbad5418a0",
"name": "xx",
"age": 18}]真實用例：
require('co-yield-breakpoint')({
files: ['./lib/**/*.js', './models/**/*.js'],
store: require('./lib/koa_yield_breakpoint_logstash'),
loggerName: '__coLogger'});store 參數最好自己定義，可以是一個 object 可以是一個實例，只需要有一個 save 方法即可。在 save 方法內可做一些自定義，比如我在 koa_yield_breakpoint_logstash.js 里添加了一些字段（如：url），同時對正常請求日志過濾了一些字段，對錯誤請求日志添加了一些字段方便 bug 追蹤。如下：
if (ctx.request) {
record.request = _.pick(ctx.request, 'headers', 'body', 'query', 'ips');}線上 API 在上了 koa-yield-breakpoint + co-yield-breakpoint 這個組合后，我又讓運維在 Kibana 作了以下 3 種圖表：
fn 的平均耗時，由高到低（根據 filename 聚合, 因為 filename 中包含行列數，唯一）
每個接口的平均耗時，由高到低（根據 url 聚合）
所有 requestId 耗時排行（對應這個 requestId 所有日志 take 值累加），由高到低
看起來效果良好，但后來運維告訴我日志打的太多了，想想也是，一個邏輯復雜的 api 的請求從開始到結束，可能執行了幾十次 yield。。討論了下，決定只采樣 10% 日志。如下：
exports.save = function save(record, ctx) {
...
if (Math.random() > 0.1 && !record.error) {// co-yield-breakpoint 的 record.error 總為 undefined
return;
}
...};注意：這里 koa-yield-breakpoint 和 co-yield-breakpoint 的日志都隨機取樣了 10%， co-yield-breakpoint 的日志倒無所謂，但 koa-yield-breakpoint 的日志則被打散了，也就是說你基本上不可能通過一個 requestId 查到完整的請求日志鏈了（step 是連續的）。另一種方案是在 koa-yield-breakpoint 中間件之前給 this 添加一個屬性：
function *(next) {
this.shouldSaveLog = Math.random() < 0.1;
yield next;};然后再 save 方法內判斷一下 shouldSaveLog 決定是否記錄這條日志，上面代碼改為：
exports.save = function save(record, ctx) {
...
if (!ctx.shouldSaveLog && !record.error) {
return;
}
...};這樣也實現了只記錄 10% 的請求日志，但這種方案是：這個請求的所有日志要么都記，要么都不記（錯誤日志除外，錯誤日志一定記）。
我們正在招聘！
[北京/武漢] 石墨文檔 做最美產品 - 尋找中國最有才華的工程師加入
免責聲明：本站發布的內容（圖片、視頻和文字）以原創、轉載和分享為主，文章觀點不代表本網站立場，如果涉及侵權請聯系站長郵箱：is@yisu.com進行舉報，并提供相關證據，一經查實，將立刻刪除涉嫌侵權內容。
