Egg上层框架CabloyJS是如何输出SQL语句日志的？

背景

在Egg开发实践中，常常会遇到一个问题：如何查看刚刚执行过的Egg组装的原生SQL语句呢？

1. 现有方案

能够直接在项目的config配置文件中添加MySQL配置debug: true。这会启用底层模块mysql的调试标志，而后输出有关SQL语句的详尽信息，效果以下：

2. 弊端

debug: true方案有以下弊端：

1. 输出信息过于详细，在实际开发中反而会干扰咱们快速查看其余日志信息
2. 没有输出SQL语句的执行时间

3. 理想方案

对于一个理想的SQL语句输出方案，咱们其实只关心两个问题：

1. Egg组装的原生SQL语句究竟是怎样的？便于咱们快速排查问题
2. SQL语句的执行时间是多少，便于咱们尽早锁定性能问题，从而获得及时解决

4. CabloyJS的方案效果

CabloyJS是基于Egg的上层开发框架，针对前面提到的两个核心问题，实现了以下效果

这种SQL语句日志的输出效果：不只一目了然能够看到刚刚执行了多少SQL语句，并且每一条SQL语句的执行时间也是历历在目。固然，顺便咱们还能看到SQL语句是由哪一个链接对象执行的（经过threadId）

实现方案

下面咱们看一下CabloyJS是如何实现的。这种实现机制也适用于其余Egg系的上层框架

假设你已经建立了一个CabloyJS的项目，下面的源码均位于CabloyJS项目内

如何建立CabloyJS项目，请参见： 快速开始

1. config定义

为了让方案更灵活，咱们先扩展一下MySQL参数的定义

node_modules/egg-born-backend/config/config.default.js

// mysql
  config.mysql = {
    clients: {
      __ebdb: {
        // debug: true,
        hook: {
          meta: {
            color: 'orange',
            long_query_time: 0,
          },
          callback: {
            onQuery,
          },
        },
      },
    },
  };

名称	说明
debug	若是为true，就是启用内置的调试标志。在这里没有启用
hook.meta	包含hook的配置参数
hook.meta.color	日志输出的颜色
hook.meta.long_query_time	若是SQL语句的执行时间超过了long_query_time(ms)，就会被输出到控制台。特别的，若是long_query_time设为0，则输出全部SQL语句
hook.callback.onQuery	为了提高灵活性，咱们能够经过onQuery提供一个自定义的回调函数，当SQL语句的执行信息准备就绪时会被自动调用

2. 改写模块ali-rds

Egg执行MySQL语句的技术栈以下：模块egg -> 模块egg-mysql -> 模块ali-rds -> 模块mysql

在这里，咱们只须要改写模块ali-rds便可

node_modules/@zhennann/ali-rds/lib/client.js

function RDSClient(options) {
  if (!(this instanceof RDSClient)) {
    return new RDSClient(options);
  }
  Operator.call(this);

  this.pool = mysql.createPool(options);

  const _hook = options.hook;
  const _getConnection = this.pool.getConnection.bind(this.pool);
  this.pool.getConnection = function(cb) {
    _getConnection(function(err, conn) {
      if (err) return cb(err, null);
      onQuery(conn, function(err) {
        if (err) return cb(err, null);
        onConnection(conn, function(err) {
          if (err) return cb(err, null);
          cb(null, conn);
        });
      });
    });
    function onConnection(conn, cb) {
      if (!_hook || !_hook.callback || !_hook.callback.onConnection) return cb(null);
      if (conn.__hook_onConnection) return cb(null);
      conn.__hook_onConnection = true;
      co.wrap(_hook.callback.onConnection)(new RDSConnection(conn)).then(function() {
        cb(null);
      }).catch(function(err) {
        cb(err);
      });
    }
    function onQuery(conn, cb) {
      if (!_hook || !_hook.callback || !_hook.callback.onQuery) return cb(null);
      if (conn.__hook_onQuery) return cb(null);
      conn.__hook_onQuery = true;
      const _query = conn.query;
      conn.query = function query(sql, values, cb) {
        const prevTime = Number(new Date());
        const sequence = _query.call(conn, sql, values, cb);
        const _callback = sequence._callback;
        sequence._callback = function(...args) {
          const ms = Number(new Date()) - prevTime;
          _hook.callback.onQuery(_hook, ms, sequence, args);
          _callback && _callback(...args);
        };
        return sequence;
      };
      cb(null);
    }
  };

  [
    'query',
    'getConnection',
  ].forEach(method => {
    this.pool[method] = promisify(this.pool[method]);
  });
}

1. 首先，拦截pool.getConnection方法
2. 当系统从数据库链接池中获取到connection对象时，执行两个回调onConnection和onQuery
3. onConnection是在第一次建立connection对象时，执行一些初始化SQL语句，好比设置一些会话级别的变量，不是这里讨论的重点
4. onQuery的做用就是拦截connection.query方法，在query执行前和执行后分别记录时间，从而获得SQL语句的执行时间，而后执行config配置中指定的回调函数hook.callback.onQuery

3. 回调hook.callback.onQuery

咱们再回头看一下config配置文件中的回调函数是如何实现的

node_modules/egg-born-backend/config/config.default.js

function onQuery(hook, ms, sequence, args) {
  if (!hook.meta.long_query_time || hook.meta.long_query_time < ms) {
    const message = `threadId: ${sequence._connection.threadId}, ${ms}ms ==> ${sequence.sql}`;
    console.log(chalk.keyword(hook.meta.color)(message));
  }
}

1. 首先判断hook.meta.long_query_time，若是为0或者小于执行时间，就会执行输出
2. 使用模块chalk，并使用指定的颜色值hook.meta.color输出SQL执行日志

4. 模块module-alias

因为咱们改写了模块ali-rds的源代码，因此咱们须要启用一个新的模块名称，在这里就是@zhennann/ali-rds，发布到npm仓库便可

那么，如何使新模块@zhennann/ali-rds生效呢？因为模块ali-rds是被模块egg-mysql所引用的。咱们若是还要改写模块egg-mysql的源码，代价就未免太大了

在这里，咱们引入模块module-alias，从而达到这样的效果：模块egg-mysql源码不变，仍然是const rds = require('ali-rds');，但实际上引用的倒是@zhennann/ali-rds

模块 module-alias的机理，请参见： https://github.com/ilearnio/module-alias

这里，咱们只需看一下如何使用模块module-alias

node_modules/egg-born-backend/index.js

const moduleAlias = require('module-alias');
moduleAlias.addAlias('ali-rds', '@zhennann/ali-rds');

结语

这样，咱们就实现了一个轻巧的方案，不只能够直接在Egg上层框架中提供缺省的SQL语句输出方案，并且还能够经过覆盖config参数hook.callback.onQuery提供自定义的输出方案