Koa 請求日誌打點工具

前一段時間開始搞優化後端 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。

4.最後用 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.js
koa-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"} +0ms

koa-yield-breakpoint matched files: ["/Users/nswbmw/node/koa-yield-breakpoint/example/routes/index.js","/Users/nswbmw/node/koa-yield-breakpoint/example/routes/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 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。

{ 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。

1.start: 請求到來時第一次打點
2.beforeYield: 上一個 yieldExpression 以後到這一個 yieldExpression 以前
3.afterYield: 這個 yieldExpression 開始到結束
4.error: 錯誤日誌，koa-yield-breakpoint 會記錄下來，而後再 throw 出去
5.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);

co-yield-breakpoint

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'
});

koa-yield-breakpoint 其餘用法

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% 的請求日誌，但這種方案是：這個請求的全部日誌要麼都記，要麼都不記（錯誤日誌除外，錯誤日誌必定記）。

最後

咱們正在招聘！

[北京/武漢] 石墨文檔 作最美產品 - 尋找中國最有才華的工程師加入