-
Notifications
You must be signed in to change notification settings - Fork 45
Commit
This commit does not belong to any branch on this repository, and may belong to a fork outside of the repository.
feat: support performance timer for more precise milliseconds (#74)
e.g.: 1.375ms better than 1ms
- Loading branch information
Showing
10 changed files
with
283 additions
and
19 deletions.
There are no files selected for viewing
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -1,5 +1,6 @@ | ||
| 'use strict'; | ||
|
|
||
| const { performance } = require('perf_hooks'); | ||
| const Benchmark = require('benchmark'); | ||
| const benchmarks = require('beautify-benchmark'); | ||
| const path = require('path'); | ||
|
|
@@ -33,6 +34,20 @@ const ctx = { | |
| const contextLogger = new ContextLogger(ctx, loggerWithoutJSON); | ||
| const contextLoggerWithJSON = new ContextLogger(ctx, loggerWithJSON); | ||
|
|
||
| const ctxUsingPerformance = { | ||
| userId: '2088102117755972', | ||
| logonId: '[email protected]', | ||
| tracer: { | ||
| traceId: 'c0a8016714537221365031005', | ||
| }, | ||
| performanceStarttime: performance.now(), | ||
| ip: '127.0.0.1', | ||
| method: 'GET', | ||
| url: '/', | ||
| }; | ||
| const contextLoggerUsingPerformance = new ContextLogger(ctxUsingPerformance, loggerWithoutJSON); | ||
| const contextLoggerWithJSONUsingPerformance = new ContextLogger(ctxUsingPerformance, loggerWithJSON); | ||
|
|
||
| const err = new Error('test error'); | ||
| err.data = { foo: 'bar' }; | ||
| err.code = 'MOCK'; | ||
|
|
@@ -52,6 +67,9 @@ suite | |
| .add('contextLogger.info(message)', () => { | ||
| contextLogger.info('hello, %s', 'world'); | ||
| }) | ||
| .add('performanceStarttime: contextLogger.info(message)', () => { | ||
| contextLoggerUsingPerformance.info('hello, %s', 'world'); | ||
| }) | ||
| .add('logger.error(err) with JSON', () => { | ||
| loggerWithJSON.error(err); | ||
| }) | ||
|
|
@@ -64,6 +82,9 @@ suite | |
| .add('contextLogger.info(message) with JSON', () => { | ||
| contextLoggerWithJSON.info('hello, %s', 'world'); | ||
| }) | ||
| .add('performanceStarttime: contextLogger.info(message) with JSON', () => { | ||
| contextLoggerWithJSONUsingPerformance.info('hello, %s', 'world'); | ||
| }) | ||
| .on('cycle', event => { | ||
| benchmarks.add(event.target); | ||
| }) | ||
|
|
@@ -78,6 +99,81 @@ suite | |
| }) | ||
| .run({ async: false }); | ||
|
|
||
| // node version: v16.13.0, date: Sat Nov 20 2021 14:05:24 GMT+0800 (中国标准时间) | ||
| // Starting... | ||
| // 10 tests completed. | ||
|
|
||
| // logger.error(err) x 378,794 ops/sec ±1.35% (91 runs sampled) | ||
| // logger.info(message) x 2,026,394 ops/sec ±1.34% (97 runs sampled) | ||
| // logger.write(message) x 7,454,818 ops/sec ±4.36% (86 runs sampled) | ||
| // contextLogger.info(message) x 1,266,091 ops/sec ±3.83% (88 runs sampled) | ||
| // performanceStarttime: contextLogger.info(message) x 1,081,355 ops/sec ±3.03% (86 runs sampled) | ||
| // logger.error(err) with JSON x 121,808 ops/sec ±2.62% (90 runs sampled) | ||
| // logger.info(message) with JSON x 513,678 ops/sec ±2.08% (91 runs sampled) | ||
| // logger.write(message) with JSON x 4,120,955 ops/sec ±2.62% (93 runs sampled) | ||
| // contextLogger.info(message) with JSON x 420,963 ops/sec ±3.39% (88 runs sampled) | ||
| // performanceStarttime: contextLogger.info(message) with JSON x 382,180 ops/sec ±3.46% (88 runs sampled) | ||
|
|
||
| // node version: v14.18.1, date: Sat Nov 20 2021 14:10:56 GMT+0800 (中国标准时间) | ||
| // Starting... | ||
| // 10 tests completed. | ||
|
|
||
| // logger.error(err) x 283,941 ops/sec ±0.93% (95 runs sampled) | ||
| // logger.info(message) x 1,204,237 ops/sec ±0.58% (92 runs sampled) | ||
| // logger.write(message) x 5,056,509 ops/sec ±0.69% (92 runs sampled) | ||
| // contextLogger.info(message) x 886,979 ops/sec ±1.05% (93 runs sampled) | ||
| // performanceStarttime: contextLogger.info(message) x 635,255 ops/sec ±1.34% (92 runs sampled) | ||
| // logger.error(err) with JSON x 93,043 ops/sec ±1.12% (91 runs sampled) | ||
| // logger.info(message) with JSON x 329,611 ops/sec ±0.88% (92 runs sampled) | ||
| // logger.write(message) with JSON x 2,483,464 ops/sec ±3.14% (87 runs sampled) | ||
| // contextLogger.info(message) with JSON x 308,370 ops/sec ±3.17% (83 runs sampled) | ||
| // performanceStarttime: contextLogger.info(message) with JSON x 282,286 ops/sec ±1.34% (93 runs sampled) | ||
|
|
||
| // node version: v12.22.7, date: Sat Nov 20 2021 14:09:42 GMT+0800 (GMT+08:00) | ||
| // Starting... | ||
| // 10 tests completed. | ||
|
|
||
| // logger.error(err) x 291,964 ops/sec ±0.81% (94 runs sampled) | ||
| // logger.info(message) x 1,314,201 ops/sec ±0.93% (92 runs sampled) | ||
| // logger.write(message) x 5,628,384 ops/sec ±0.79% (94 runs sampled) | ||
| // contextLogger.info(message) x 900,788 ops/sec ±1.42% (89 runs sampled) | ||
| // performanceStarttime: contextLogger.info(message) x 669,698 ops/sec ±1.50% (89 runs sampled) | ||
| // logger.error(err) with JSON x 97,022 ops/sec ±1.57% (88 runs sampled) | ||
| // logger.info(message) with JSON x 357,988 ops/sec ±1.03% (91 runs sampled) | ||
| // logger.write(message) with JSON x 2,917,091 ops/sec ±1.10% (87 runs sampled) | ||
| // contextLogger.info(message) with JSON x 341,035 ops/sec ±1.62% (91 runs sampled) | ||
| // performanceStarttime: contextLogger.info(message) with JSON x 295,930 ops/sec ±1.42% (90 runs sampled) | ||
|
|
||
| // node version: v10.24.1, date: Sat Nov 20 2021 14:08:19 GMT+0800 (GMT+08:00) | ||
| // Starting... | ||
| // 10 tests completed. | ||
|
|
||
| // logger.error(err) x 184,461 ops/sec ±5.58% (82 runs sampled) | ||
| // logger.info(message) x 1,279,248 ops/sec ±2.01% (83 runs sampled) | ||
| // logger.write(message) x 5,638,776 ops/sec ±1.52% (80 runs sampled) | ||
| // contextLogger.info(message) x 845,329 ops/sec ±1.60% (81 runs sampled) | ||
| // performanceStarttime: contextLogger.info(message) x 662,304 ops/sec ±2.72% (82 runs sampled) | ||
| // logger.error(err) with JSON x 67,005 ops/sec ±2.26% (81 runs sampled) | ||
| // logger.info(message) with JSON x 344,886 ops/sec ±1.85% (89 runs sampled) | ||
| // logger.write(message) with JSON x 2,864,012 ops/sec ±1.66% (86 runs sampled) | ||
| // contextLogger.info(message) with JSON x 254,776 ops/sec ±1.71% (89 runs sampled) | ||
| // performanceStarttime: contextLogger.info(message) with JSON x 229,181 ops/sec ±1.62% (89 runs sampled) | ||
|
|
||
| // node version: v8.17.0, date: Sat Nov 20 2021 14:06:59 GMT+0800 (CST) | ||
| // Starting... | ||
| // 10 tests completed. | ||
|
|
||
| // logger.error(err) x 173,509 ops/sec ±2.36% (78 runs sampled) | ||
| // logger.info(message) x 1,418,705 ops/sec ±2.04% (90 runs sampled) | ||
| // logger.write(message) x 4,905,138 ops/sec ±1.46% (93 runs sampled) | ||
| // contextLogger.info(message) x 945,955 ops/sec ±3.21% (85 runs sampled) | ||
| // performanceStarttime: contextLogger.info(message) x 740,081 ops/sec ±3.33% (83 runs sampled) | ||
| // logger.error(err) with JSON x 68,264 ops/sec ±2.70% (81 runs sampled) | ||
| // logger.info(message) with JSON x 371,275 ops/sec ±2.79% (90 runs sampled) | ||
| // logger.write(message) with JSON x 2,497,323 ops/sec ±5.17% (81 runs sampled) | ||
| // contextLogger.info(message) with JSON x 260,842 ops/sec ±3.12% (85 runs sampled) | ||
| // performanceStarttime: contextLogger.info(message) with JSON x 226,953 ops/sec ±3.58% (82 runs sampled) | ||
|
|
||
| // node version: v4.4.7, date: Tue Jul 26 2016 00:27:29 GMT+0800 (CST) | ||
| // Starting... | ||
| // 8 tests completed. | ||
|
|
||
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,142 @@ | ||
| 'use strict'; | ||
|
|
||
| const { performance } = require('perf_hooks'); | ||
| const Benchmark = require('benchmark'); | ||
| const benchmarks = require('beautify-benchmark'); | ||
|
|
||
| function DateTimer(starttime) { | ||
| return Date.now() - starttime; | ||
| } | ||
|
|
||
| function PerformanceTimer(starttime) { | ||
| return performance.now() - starttime; | ||
| } | ||
|
|
||
| function PerformanceTimerFixedString(starttime) { | ||
| return (performance.now() - starttime).toFixed(3); | ||
| } | ||
|
|
||
| function PerformanceTimerMicrosecond(starttime) { | ||
| return Math.floor((performance.now() - starttime) * 1000); | ||
| } | ||
|
|
||
| function PerformanceTimerMillisecond(starttime) { | ||
| return Math.floor((performance.now() - starttime) * 1000) / 1000; | ||
| } | ||
|
|
||
| const suite = new Benchmark.Suite(); | ||
|
|
||
| const dateNowStarttime = Date.now(); | ||
| const performanceNowStarttime = performance.now(); | ||
|
|
||
| suite | ||
| .add('DateTimer()', () => { | ||
| DateTimer(dateNowStarttime); | ||
| }) | ||
| .add('PerformanceTimer()', () => { | ||
| PerformanceTimer(performanceNowStarttime); | ||
| }) | ||
| .add('PerformanceTimerFixedString()', () => { | ||
| PerformanceTimerFixedString(performanceNowStarttime); | ||
| }) | ||
| .add('PerformanceTimerMicrosecond()', () => { | ||
| PerformanceTimerMicrosecond(performanceNowStarttime); | ||
| }) | ||
| .add('PerformanceTimerMillisecond()', () => { | ||
| PerformanceTimerMillisecond(performanceNowStarttime); | ||
| }) | ||
| .on('cycle', event => { | ||
| benchmarks.add(event.target); | ||
| }) | ||
| .on('start', () => { | ||
| console.log('\n node version: %s, date: %s\n Starting...', process.version, Date()); | ||
| console.log(' DateTimer(dateNowStarttime) %sms', | ||
| DateTimer(dateNowStarttime)); | ||
| console.log(' PerformanceTimer(performanceNowStarttime) %sms', | ||
| PerformanceTimer(performanceNowStarttime)); | ||
| console.log(' PerformanceTimerFixedString(performanceNowStarttime) %sms', | ||
| PerformanceTimerFixedString(performanceNowStarttime)); | ||
| console.log(' PerformanceTimerMicrosecond(performanceNowStarttime) %sμs', | ||
| PerformanceTimerMicrosecond(performanceNowStarttime)); | ||
| console.log(' PerformanceTimerMillisecond(performanceNowStarttime) %sms', | ||
| PerformanceTimerMillisecond(performanceNowStarttime)); | ||
| }) | ||
| .on('complete', () => { | ||
| benchmarks.log(); | ||
| process.exit(0); | ||
| }) | ||
| .run({ async: false }); | ||
|
|
||
| // node version: v16.13.0, date: Sat Nov 20 2021 14:01:59 GMT+0800 (中国标准时间) | ||
| // Starting... | ||
| // DateTimer(dateNowStarttime) 3ms | ||
| // PerformanceTimer(performanceNowStarttime) 3.4372918605804443ms | ||
| // PerformanceTimerFixedString(performanceNowStarttime) 3.467ms | ||
| // PerformanceTimerMicrosecond(performanceNowStarttime) 3592μs | ||
| // PerformanceTimerMillisecond(performanceNowStarttime) 3.62ms | ||
| // 5 tests completed. | ||
|
|
||
| // DateTimer() x 29,062,254 ops/sec ±0.22% (98 runs sampled) | ||
| // PerformanceTimer() x 47,283,718 ops/sec ±0.07% (96 runs sampled) | ||
| // PerformanceTimerFixedString() x 7,022,557 ops/sec ±0.15% (94 runs sampled) | ||
| // PerformanceTimerMicrosecond() x 35,585,959 ops/sec ±0.09% (101 runs sampled) | ||
| // PerformanceTimerMillisecond() x 25,969,450 ops/sec ±0.07% (102 runs sampled) | ||
|
|
||
| // node version: v14.18.1, date: Sat Nov 20 2021 14:01:08 GMT+0800 (中国标准时间) | ||
| // Starting... | ||
| // DateTimer(dateNowStarttime) 6ms | ||
| // PerformanceTimer(performanceNowStarttime) 5.301500082015991ms | ||
| // PerformanceTimerFixedString(performanceNowStarttime) 5.343ms | ||
| // PerformanceTimerMicrosecond(performanceNowStarttime) 5385μs | ||
| // PerformanceTimerMillisecond(performanceNowStarttime) 5.438ms | ||
| // 5 tests completed. | ||
|
|
||
| // DateTimer() x 20,540,537 ops/sec ±0.77% (96 runs sampled) | ||
| // PerformanceTimer() x 9,779,834 ops/sec ±0.75% (89 runs sampled) | ||
| // PerformanceTimerFixedString() x 3,180,287 ops/sec ±0.34% (92 runs sampled) | ||
| // PerformanceTimerMicrosecond() x 9,726,309 ops/sec ±0.55% (97 runs sampled) | ||
| // PerformanceTimerMillisecond() x 9,639,512 ops/sec ±0.60% (94 runs sampled) | ||
|
|
||
| // node version: v12.22.7, date: Sat Nov 20 2021 14:00:16 GMT+0800 (GMT+08:00) | ||
| // Starting... | ||
| // DateTimer(dateNowStarttime) 6ms | ||
| // PerformanceTimer(performanceNowStarttime) 6.380917072296143ms | ||
| // PerformanceTimerFixedString(performanceNowStarttime) 6.426ms | ||
| // PerformanceTimerMicrosecond(performanceNowStarttime) 6470μs | ||
| // PerformanceTimerMillisecond(performanceNowStarttime) 6.513ms | ||
| // 5 tests completed. | ||
|
|
||
| // DateTimer() x 20,966,403 ops/sec ±0.81% (97 runs sampled) | ||
| // PerformanceTimer() x 22,378,897 ops/sec ±0.07% (96 runs sampled) | ||
| // PerformanceTimerFixedString() x 3,187,744 ops/sec ±0.14% (93 runs sampled) | ||
| // PerformanceTimerMicrosecond() x 21,360,658 ops/sec ±0.98% (93 runs sampled) | ||
| // PerformanceTimerMillisecond() x 15,127,442 ops/sec ±0.60% (97 runs sampled) | ||
|
|
||
| // node version: v10.24.1, date: Sat Nov 20 2021 13:59:28 GMT+0800 (GMT+08:00) | ||
| // Starting... | ||
| // DateTimer(dateNowStarttime) 16ms | ||
| // PerformanceTimer(performanceNowStarttime) 16.252916932106018ms | ||
| // PerformanceTimerFixedString(performanceNowStarttime) 16.491ms | ||
| // PerformanceTimerMicrosecond(performanceNowStarttime) 16548μs | ||
| // PerformanceTimerMillisecond(performanceNowStarttime) 22.212ms | ||
| // 5 tests completed. | ||
|
|
||
| // DateTimer() x 22,349,551 ops/sec ±0.33% (90 runs sampled) | ||
| // PerformanceTimer() x 30,092,603 ops/sec ±0.96% (89 runs sampled) | ||
| // PerformanceTimerFixedString() x 3,248,977 ops/sec ±2.51% (83 runs sampled) | ||
| // PerformanceTimerMicrosecond() x 30,358,443 ops/sec ±0.24% (89 runs sampled) | ||
| // PerformanceTimerMillisecond() x 18,356,502 ops/sec ±0.70% (93 runs sampled) | ||
| // node version: v8.17.0, date: Sat Nov 20 2021 13:58:23 GMT+0800 (CST) | ||
| // Starting... | ||
| // DateTimer(dateNowStarttime) 4ms | ||
| // PerformanceTimer(performanceNowStarttime) 3.2330000400543213ms | ||
| // PerformanceTimerFixedString(performanceNowStarttime) 3.285ms | ||
| // PerformanceTimerMicrosecond(performanceNowStarttime) 3332μs | ||
| // PerformanceTimerMillisecond(performanceNowStarttime) 3.481ms | ||
| // 5 tests completed. | ||
|
|
||
| // DateTimer() x 15,125,135 ops/sec ±0.31% (98 runs sampled) | ||
| // PerformanceTimer() x 25,598,467 ops/sec ±0.30% (94 runs sampled) | ||
| // PerformanceTimerFixedString() x 3,406,506 ops/sec ±0.38% (90 runs sampled) | ||
| // PerformanceTimerMicrosecond() x 26,842,589 ops/sec ±0.16% (95 runs sampled) | ||
| // PerformanceTimerMillisecond() x 26,352,137 ops/sec ±0.42% (89 runs sampled) |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Oops, something went wrong.