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提供自定義的輸出方案