feat: support better logger timer in precise milliseconds

detail see eggjs/egg-logger#74

How to use:

```js
// config.js

exports.logger = {
  enablePerformanceTimer: true,
};
```

app/extend/context.js

@@ -1,5 +1,6 @@
 'use strict';
 
+const { performance } = require('perf_hooks');
 const delegate = require('delegates');
 const { assign } = require('utility');
 const eggUtils = require('egg-core').utils;
@@ -219,19 +220,21 @@ const proto = module.exports = {
   // e.g.: https://github.com/eggjs/egg-mock/pull/78
   _runInBackground(scope) {
     const ctx = this;
-    const start = Date.now();
+    const start = performance.now();
     /* istanbul ignore next */
     const taskName = scope._name || scope.name || eggUtils.getCalleeFromStack(true);
     // use setImmediate to ensure all sync logic will run async
     return new Promise(resolve => setImmediate(resolve))
       // use app.toAsyncFunction to support both generator function and async function
       .then(() => ctx.app.toAsyncFunction(scope)(ctx))
       .then(() => {
-        ctx.coreLogger.info('[egg:background] task:%s success (%dms)', taskName, Date.now() - start);
+        ctx.coreLogger.info('[egg:background] task:%s success (%dms)',
+          taskName, Math.floor((performance.now() - start) * 1000) / 1000);
       })
       .catch(err => {
         // background task process log
-        ctx.coreLogger.info('[egg:background] task:%s fail (%dms)', taskName, Date.now() - start);
+        ctx.coreLogger.info('[egg:background] task:%s fail (%dms)',
+          taskName, Math.floor((performance.now() - start) * 1000) / 1000);
 
         // emit error when promise catch, and set err.runInBackground flag
         err.runInBackground = true;

config/config.default.js

@@ -249,6 +249,8 @@ module.exports = appInfo => {
    * @property {String} coreLogName - file name of coreLogger
    * @property {String} agentLogName - file name of agent worker log
    * @property {Object} coreLogger - custom config of coreLogger
+   * @property {Boolean} allowDebugAtProd - allow debug log at prod, defaults to false
+   * @property {Boolean} enablePerformanceTimer - using performance.now() timer instead of Date.now() for more more precise milliseconds, defaults to false. e.g.: logger will set 1.456ms instead of 1ms.
    */
   config.logger = {
     dir: path.join(appInfo.root, 'logs', appInfo.name),
@@ -265,6 +267,7 @@ module.exports = appInfo => {
     errorLogName: 'common-error.log',
     coreLogger: {},
     allowDebugAtProd: false,
+    enablePerformanceTimer: false,
   };
 
   /**

index.d.ts

@@ -217,10 +217,12 @@ declare module 'egg' {
   export interface EggLoggerConfig extends RemoveSpecProp<EggLoggersOptions, 'type'> {
     /** custom config of coreLogger */
     coreLogger?: Partial<EggLoggerOptions>;
-    /** allow debug log at prod, defaults to true */
+    /** allow debug log at prod, defaults to `false` */
     allowDebugAtProd?: boolean;
     /** disable logger console after app ready. defaults to `false` on local and unittest env, others is `true`. */
     disableConsoleAfterReady?: boolean;
+    /** using performance.now() timer instead of Date.now() for more more precise milliseconds, defaults to `false`. e.g.: logger will set 1.456ms instead of 1ms. */
+    enablePerformanceTimer?: boolean;
   }
 
   /** Custom Loader Configuration */
@@ -329,7 +331,8 @@ declare module 'egg' {
      * @property {String} coreLogName - file name of coreLogger
      * @property {String} agentLogName - file name of agent worker log
      * @property {Object} coreLogger - custom config of coreLogger
-     * @property {Boolean} allowDebugAtProd - allow debug log at prod, defaults to true
+     * @property {Boolean} allowDebugAtProd - allow debug log at prod, defaults to false
+     * @property {Boolean} enablePerformanceTimer - using performance.now() timer instead of Date.now() for more more precise milliseconds, defaults to false. e.g.: logger will set 1.456ms instead of 1ms.
      */
     logger: EggLoggerConfig;
 
@@ -924,6 +927,11 @@ declare module 'egg' {
      */
     starttime: number;
 
+    /**
+     * Request start timer using `performance.now()`
+     */
+    performanceStartTime?: number;
+
     /**
      * http request helper base on httpclient, it will auto save httpclient log.
      * Keep the same api with httpclient.request(url, args).

lib/egg.js

@@ -1,5 +1,6 @@
 'use strict';
 
+const { performance } = require('perf_hooks');
 const path = require('path');
 const fs = require('fs');
 const ms = require('ms');
@@ -547,6 +548,14 @@ class EggApplication extends EggCore {
      * @member {Number} Context#starttime
      */
     context.starttime = Date.now();
+
+    if (this.config.logger.enablePerformanceTimer) {
+      /**
+       * Request start timer using `performance.now()`
+       * @member {Number} Context#performanceStarttime
+       */
+      context.performanceStarttime = performance.now();
+    }
     return context;
   }
 

package.json

@@ -116,7 +116,7 @@
     "url": "https://github.com/eggjs/egg.git"
   },
   "engines": {
-    "node": ">= 8.0.0"
+    "node": ">= 8.5.0"
   },
   "license": "MIT"
 }

test/app/extend/context.test.js

@@ -259,10 +259,10 @@ describe('test/app/extend/context.test.js', () => {
       assert(/background run result file size: \d+/.test(log));
       assert(/background run anonymous result file size: \d+/.test(log));
       assert(
-        /\[egg:background] task:saveUserInfo success \(\d+ms\)/.test(fs.readFileSync(path.join(logdir, 'egg-web.log'), 'utf8'))
+        /\[egg:background] task:saveUserInfo success \([\d\.]+ms\)/.test(fs.readFileSync(path.join(logdir, 'egg-web.log'), 'utf8'))
       );
       assert(
-        /\[egg:background] task:.*?app[\/\\]controller[\/\\]home\.js:\d+:\d+ success \(\d+ms\)/.test(fs.readFileSync(path.join(logdir, 'egg-web.log'), 'utf8'))
+        /\[egg:background] task:.*?app[\/\\]controller[\/\\]home\.js:\d+:\d+ success \([\d\.]+ms\)/.test(fs.readFileSync(path.join(logdir, 'egg-web.log'), 'utf8'))
       );
     });
 
@@ -277,7 +277,7 @@ describe('test/app/extend/context.test.js', () => {
       const log = fs.readFileSync(path.join(logdir, 'ctx-background-web.log'), 'utf8');
       assert(/background run result file size: \d+/.test(log));
       assert(
-        /\[egg:background] task:customTaskName success \(\d+ms\)/.test(fs.readFileSync(path.join(logdir, 'egg-web.log'), 'utf8'))
+        /\[egg:background] task:customTaskName success \([\d\.]+ms\)/.test(fs.readFileSync(path.join(logdir, 'egg-web.log'), 'utf8'))
       );
     });
 
@@ -302,7 +302,7 @@ describe('test/app/extend/context.test.js', () => {
       const log = fs.readFileSync(path.join(logdir, 'common-error.log'), 'utf8');
       assert(/ENOENT: no such file or directory/.test(log));
       assert(
-        /\[egg:background] task:mockError fail \(\d+ms\)/.test(fs.readFileSync(path.join(logdir, 'egg-web.log'), 'utf8'))
+        /\[egg:background] task:mockError fail \([\d\.]+ms\)/.test(fs.readFileSync(path.join(logdir, 'egg-web.log'), 'utf8'))
       );
     });
 
@@ -335,10 +335,10 @@ describe('test/app/extend/context.test.js', () => {
       assert(/background run result file size: \d+/.test(log));
       assert(/background run anonymous result file size: \d+/.test(log));
       assert(
-        /\[egg:background] task:saveUserInfo success \(\d+ms\)/.test(fs.readFileSync(path.join(logdir, 'egg-web.log'), 'utf8'))
+        /\[egg:background] task:saveUserInfo success \([\d\.]+ms\)/.test(fs.readFileSync(path.join(logdir, 'egg-web.log'), 'utf8'))
       );
       assert(
-        /\[egg:background] task:.*?app[\/\\]controller[\/\\]home\.js:\d+:\d+ success \(\d+ms\)/.test(fs.readFileSync(path.join(logdir, 'egg-web.log'), 'utf8'))
+        /\[egg:background] task:.*?app[\/\\]controller[\/\\]home\.js:\d+:\d+ success \([\d\.]+ms\)/.test(fs.readFileSync(path.join(logdir, 'egg-web.log'), 'utf8'))
       );
     });
 
@@ -352,7 +352,7 @@ describe('test/app/extend/context.test.js', () => {
       const log = fs.readFileSync(path.join(logdir, 'ctx-background-web.log'), 'utf8');
       assert(/background run result file size: \d+/.test(log));
       assert(
-        /\[egg:background] task:customTaskName success \(\d+ms\)/.test(fs.readFileSync(path.join(logdir, 'egg-web.log'), 'utf8'))
+        /\[egg:background] task:customTaskName success \([\d\.]+ms\)/.test(fs.readFileSync(path.join(logdir, 'egg-web.log'), 'utf8'))
       );
     });
 
@@ -376,7 +376,7 @@ describe('test/app/extend/context.test.js', () => {
       const log = fs.readFileSync(path.join(logdir, 'common-error.log'), 'utf8');
       assert(/ENOENT: no such file or directory/.test(log));
       assert(
-        /\[egg:background] task:mockError fail \(\d+ms\)/.test(fs.readFileSync(path.join(logdir, 'egg-web.log'), 'utf8'))
+        /\[egg:background] task:mockError fail \([\d\.]+ms\)/.test(fs.readFileSync(path.join(logdir, 'egg-web.log'), 'utf8'))
       );
     });
   });

test/fixtures/apps/app-enablePerformanceTimer-true/app/controller/home.js

@@ -0,0 +1,3 @@
+module.exports = async (ctx) => {
+  ctx.body = 'hello performanceStarttime: ' + ctx.performanceStarttime;
+};

test/fixtures/apps/app-enablePerformanceTimer-true/app/router.js

@@ -0,0 +1,3 @@
+module.exports = app => {
+  app.get('home', '/', 'home');
+};

test/fixtures/apps/app-enablePerformanceTimer-true/config/config.default.js

@@ -0,0 +1,8 @@
+'use strict';
+
+exports.logger = {
+  level: 'DEBUG',
+  enablePerformanceTimer: true,
+};
+
+exports.keys = 'foo';

test/fixtures/apps/app-enablePerformanceTimer-true/config/config.unittest.js

@@ -0,0 +1,5 @@
+'use strict';
+
+exports.logger = {
+  consoleLevel: 'NONE',
+};

test/fixtures/apps/app-enablePerformanceTimer-true/package.json

@@ -0,0 +1,3 @@
+{
+  "name": "app-enablePerformanceTimer-true"
+}

test/fixtures/apps/tracer-demo/tracer.js

@@ -13,7 +13,7 @@ module.exports = app => {
     if (!req.ctx.traceId) {
       req.ctx.traceId = uuid.v1();
     }
-    req.starttime = Date.now();
+    req.starttime = performance.now();
     req.args.headers = req.args.headers || {};
     req.args.headers['x-request-id'] = req.ctx.traceId;
     req.args.method = req.args.method || 'GET';
@@ -26,6 +26,6 @@ module.exports = app => {
     const res = response.res;
     app.logger.info('[httpclient] [%s] %s %s end, status: %s, use: %s',
       req.ctx.traceId, req.args.method, req.url,
-      res.status, Date.now() - req.starttime);
+      res.status, Math.floor((performance.now() - starttime) * 1000) / 1000);
   });
 };

test/lib/core/context_performance_starttime.test.js

@@ -0,0 +1,27 @@
+'use strict';
+
+const assert = require('assert');
+const utils = require('../../utils');
+
+describe('test/lib/core/context_performance_starttime.test.js', () => {
+  let app;
+
+  before(() => {
+    app = utils.app('apps/app-enablePerformanceTimer-true');
+    return app.ready();
+  });
+
+  it('should set ctx.performanceStarttime', () => {
+    const ctx = app.mockContext();
+    assert(ctx.performanceStarttime);
+    assert(ctx.performanceStarttime > 0);
+    assert(typeof ctx.performanceStarttime === 'number');
+  });
+
+  it('should use ctx.performanceStarttime on controller', async () => {
+    const res = await app.httpRequest()
+      .get('/');
+    assert(res.status === 200);
+    assert(/hello performanceStarttime: \d+\.\d+/.test(res.text));
+  });
+});