Some time ago, I started to optimize the performance of the back-end API, but I found that I had no way to start. Although THERE are some rough and scattered logs in Kibana, I didn’t see anything. The goal is to log API requests and find out which interface is slow, preferably specifically which function is slow.
It is necessary to keep a log, how to do log is a problem. If directly inserted into the code log code is not only invasive and heavy workload, also not flexible, so consider how to do intelligent automatic log. The Bay framework we use for the graphite back end (based on the Koa@1 secondary development, which basically you can think of as Koa) uses a lot of yield in the controller, so consider whether you can use yield before and after the expression, I researched esprima and EscodeGen.
After a few days of hard work, koa-yield-breakpoint was born.
koa-yield-breakpoint
Koa-yield-breakpoint is a tool for setting the yield before and after controllers or routes. Instead of inserting a line of log code, you configure it at the time of introduction. You can record the scene before and after the yield expression when each request arrives, as in:
- The row and column number of the yield expression (filename)
- The yield expression is the number of steps to execute.
- Yield expression string form (fn)
- Time taken to execute the yield expression (take)
- The result of executing the yield expression
- Yield expression at the time of the field (this), through which you can also add custom fields
Principle:
- Module.prototype._compile (” require “, “require”, “require”, “compile”);
shimmer.wrap(Module.prototype, '_compile', function (__compile) { return function koaBreakpointCompile(content, filename) { if (!_.includes(filenames, filename)) { return __compile.call(this, content, filename); } ... }; }); Copy the code - Esprima parses the code to generate the AST. Such as:
'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; }; Copy the codeThe following AST is generated:
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 } } } Copy the codeThe relevant source code is as follows:
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); } Copy the code - Traverse to find the YieldExpression nodes, which are then wrapped as follows to generate an AST to replace the original nodes.
global.logger( this, function*(){ return YieldExpression }, YieldExpressionString, filename ); Copy the codeThe relevant source code is as follows:
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); Copy the codeThe role of findYieldAndWrapLogger is to walk through the AST and replace the YieldExpression with the AST of the new YieldExpression wrapped in the logging function.
- Finally, the AST generates code using EscodeGen (soucemap is supported, so the error stack corresponds to the correct number of lines).
Core: Generate a requestId (type UUID) to mount to this on each request as it comes in (if the project already has a requestId, which can be specified by configuration), so that the logs can be connected via requestId.
Features: It can record the flow of each request (and even check the request of a user in a certain period of time), and the field and return value of each step (step) of each request for debugging or bug detection. Of course, only yield expressions can be used.
Take a chestnut
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');
});
Copy the coderoutes/index.js
'use strict';
const route = require('koa-route');
const users = require('./users');
module.exports = function (app) {
app.use(route.get('/users', users.getUsers));
};
Copy the coderoutes/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;
};
Copy the codeRun:
DEBUG=koa-yield-breakpoint node app.js
Copy the codeThe terminal print is as follows:
➜ example git:(master) DEBUG=koa-yield-breakpoint node app.js koa-yield-breakpoint options: {"files":["./routes/*.js"],"nodir":true,"absolute":true,"filter":{"ctx":["state","params"],"request":["method","path","h eader","query","body"],"response":["status","body"]},"loggerName":"logger","requestIdPath":"requestId"} +0ms koa-yield-breakpoint matched files: ["/Users/nswbmw/node/koa-yield-breakpoint/example/routes/index.js","/Users/nswbmw/node/koa-yield-breakpoint/example/rout es/users.js"] +9ms koa-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)); }; +73ms koa-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; }; +15ms listening on 3000Copy the codeWe can see that routes/users.js is replaced with:
'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;
};
Copy the codeWhy wrap the yield expression like this?
global.logger(
this,
function*(){
return YieldExpression
},
YieldExpressionString,
filename
);
Copy the codeInstead of:
global.logger(
this,
function(){
return YieldExpression
},
YieldExpressionString,
filename
);
Copy the codeOr:
global.logger(
this,
yield YieldExpression,
YieldExpressionString,
filename
);
Copy the codeBecause considering YieldExpression may cause Esprima to fail to parse:
- User.find(yield xxx)
- User.find(http://this.xxx)
Therefore, we can only put it into GeneratorFunction. In addition, we don’t need:
global.logger(
this,
function*(){
return yield YieldExpression
},
YieldExpressionString,
filename
);
Copy the codeBecause this would cause Esprima to parse an infinite loop, the yield in logger is removed.
Access localhost:3000/users and the terminal prints:
{ 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 }
Copy the codeNote: Type is one of [‘start’, ‘beforeYield’, ‘afterYield’, ‘error’, ‘end’] and take is in ms.
- Start: Initiates the first call when the request arrives
- BeforeYield: After the last yieldExpression to before this yieldExpression
- AfterYield: This yieldExpression begins and ends
- Error: An error log is logged by koa-yield-breakpoint and then thrown out
- “End” : indicates the end of the request
The real case
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 Not wrapping Logger if (yieldExpression === 'next') {return {wrapYield: false, deep: false }; } if (yieldExpression.match(/^db\.sequelize\.transaction/)) { return { wrapYield: true, deep: false }; }}}); . app.use(koaYieldBreakpoint);Copy the codeco-yield-breakpoint
Koa-yield-breakpoint is used primarily in KOA routes, controllers, or middlewares files. Co-yield-breakpoint is mainly used to dot normal yield expressions (files under lib or models, for example) (there is no requestId, so the log is fragmented and is only used to calculate the average time), The implementation principle is similar to koA-yield-breakpoint, which will not be described here.
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));
Copy the codeThe terminal print is as follows:
{ "filename": "/Users/nswbmw/node/co-yield-breakpoint/example/foo.js:9:2", "timestamp": "The 2016-11-10 T13:53:33. 053 z", "fn" : "mongolass. Model (' users'). The 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": "The 2016-11-10 T13:53:33. 060 z", "fn" : "mongolass. Model (' users'). The find ()", "result" : [{" _id ": "58247bdd3fb205dbad5418a0", "name": "xx", "age": 18 }], "take": 7 } users: [{ "_id": "58247bdd3fb205dbad5418a0", "name": "xx", "age": 18 }]Copy the codeReal use cases:
require('co-yield-breakpoint')({
files: ['./lib/**/*.js', './models/**/*.js'],
store: require('./lib/koa_yield_breakpoint_logstash'),
loggerName: '__coLogger'
});
Copy the codeKoa-yield-breakpoint other usage
The store parameter is best defined by yourself. It can be an object or an instance, and only a save method is required. For example, I added some fields (such as URL) to koa_yield_breakpoint_logstash. Js. I also filtered some fields from the normal request log and added some fields from the error request log for bug tracking. As follows:
if (ctx.request) {
record.request = _.pick(ctx.request, 'headers', 'body', 'query', 'ips');
}
Copy the codeWatch out for too many entries
After applying the koa-yield-breakpoint + co-yield-breakpoint combination to the online API, I asked OPS to create the following 3 diagrams in Kibana:
- Average time taken by FN, from high to low (aggregated by filename, because filename contains the number of rows and columns, unique)
- Average elapsed time per interface, from highest to lowest (aggregated by URL)
- Ranking of all requestId time consumption (the total take values of all requestId logs) in descending order
It seemed to work well, but then operations told me that logging was too much, and to think about it, a request from a logically complex API might perform dozens of yields from start to finish. After some discussion, we decided to sample only 10% of the logs. As follows:
exports.save = function save(record, ctx) { ... If (math.random () > 0.1 &&! Record. error) {// Co-yield-breakpoint record.error always undefined return; }... };Copy the codeNote: Here the koa-yield-breakpoint and co-yield-breakpoint logs are randomly sampled at 10%, and the co-yield-breakpoint logs don’t matter, The koa-yield-breakpoint log is shredded, meaning that it is almost impossible to trace the entire request log chain through a requestId (steps are sequential). Another option is to add an attribute to this before the Koa-yield-breakpoint middleware:
Function *(next) {this.shouldsavelog = math.random () < 0.1; yield next; };Copy the codeShouldSaveLog (); shouldSaveLog ();
exports.save = function save(record, ctx) { ... if (! ctx.shouldSaveLog && ! record.error) { return; }... };Copy the codeThis also allows only 10% of the request logs to be logged, but in this scenario, all or none of the logs for the request (except the error logs, which are always logged) are logged.
The last
We are hiring!
[Beijing/Wuhan] Graphite document to make the most beautiful products – looking for the most talented engineers in China to join us