PR Checklist
Please check if your PR fulfills the following requirements:
- [x] The commit message follows our guidelines: https://github.com/nestjs/nest/blob/master/CONTRIBUTING.md
- [ ] Tests for the changes have been added (for bug fixes / features)
- [ ] Docs have been added / updated (for bug fixes / features)
PR Type
What kind of change does this PR introduce?
- [ ] Bugfix
- [ ] Feature
- [ ] Code style update (formatting, local variables)
- [x] Refactoring (no functional changes, no api changes)
- [ ] Build related changes
- [ ] CI related changes
- [ ] Other... Please describe:
What is the current behavior?
This is the profiler information when we call #log
method 10.000 times:
[Bottom up (heavy) profile]:
Note: percentage shows a share of a particular caller in the total
amount of its parent calls.
Callers occupying less than 1.0% are not shown.
ticks parent name
958 56.8% /home/h4ad/.asdf/installs/nodejs/12.22.12/bin/node
763 79.6% v8::internal::Builtin_DatePrototypeToLocaleString(int, unsigned long*, v8::internal::Isolate*)
560 73.4% LazyCompile: *getTimestamp /home/h4ad/Projects/opensource/performance-test-nestjs/test-performance/node_modules/@nestjs/common/services/console-logger.service.js:104:17
510 91.1% LazyCompile: *log /home/h4ad/Projects/opensource/performance-test-nestjs/test-performance/node_modules/@nestjs/common/services/console-logger.service.js:28:8
510 100.0% LazyCompile: *log /home/h4ad/Projects/opensource/performance-test-nestjs/test-performance/node_modules/@nestjs/common/services/logger.service.js:36:8
510 100.0% LazyCompile: ~descriptor.value /home/h4ad/Projects/opensource/performance-test-nestjs/test-performance/node_modules/@nestjs/common/services/logger.service.js:155:33
50 8.9% LazyCompile: *printMessages /home/h4ad/Projects/opensource/performance-test-nestjs/test-performance/node_modules/@nestjs/common/services/console-logger.service.js:115:18
50 100.0% LazyCompile: ~log /home/h4ad/Projects/opensource/performance-test-nestjs/test-performance/node_modules/@nestjs/common/services/console-logger.service.js:28:8
50 100.0% LazyCompile: *log /home/h4ad/Projects/opensource/performance-test-nestjs/test-performance/node_modules/@nestjs/common/services/logger.service.js:36:8
203 26.6% LazyCompile: ~getTimestamp /home/h4ad/Projects/opensource/performance-test-nestjs/test-performance/node_modules/@nestjs/common/services/console-logger.service.js:104:17
179 88.2% LazyCompile: ~formatMessage /home/h4ad/Projects/opensource/performance-test-nestjs/test-performance/node_modules/@nestjs/common/services/console-logger.service.js:131:18
179 100.0% LazyCompile: ~<anonymous> /home/h4ad/Projects/opensource/performance-test-nestjs/test-performance/node_modules/@nestjs/common/services/console-logger.service.js:116:26
179 100.0% /home/h4ad/.asdf/installs/nodejs/12.22.12/bin/node
24 11.8% LazyCompile: *printMessages /home/h4ad/Projects/opensource/performance-test-nestjs/test-performance/node_modules/@nestjs/common/services/console-logger.service.js:115:18
24 100.0% LazyCompile: ~log /home/h4ad/Projects/opensource/performance-test-nestjs/test-performance/node_modules/@nestjs/common/services/console-logger.service.js:28:8
24 100.0% LazyCompile: ~log /home/h4ad/Projects/opensource/performance-test-nestjs/test-performance/node_modules/@nestjs/common/services/logger.service.js:36:8
Source
As you can see, getTimestamp
consumes most of the execution time, which doesn't make sense, I did some CPU profiling and I found this:
normal_logger_nodejs12.cpuprofile.zip
The #getTimestamp
method took 1ms, in another test that I did, this function
When we run again on nodejs16 or nodejs19:
The #getTimestamp
method took 13ms (I think I found a regression on NodeJS).
normal_logger_nodejs16.cpuprofile.zip
normal_logger_nodejs19.cpuprofile.zip
Also, decorators like WrapBuffer
tends to not be optimized by V8, so this could be another point of optimization.
Issue Number: N/A
What is the new behavior?
So, to solve the issue with #getTimestamp
, I started using Intl.DateTimeFormat
API,
and for the decorator WrapBuffer
, I just refactor to use a function.
The final profiler information became:
[Bottom up (heavy) profile]:
Note: percentage shows a share of a particular caller in the total
amount of its parent calls.
Callers occupying less than 1.0% are not shown.
ticks parent name
207 45.3% /home/h4ad/.asdf/installs/nodejs/12.22.12/bin/node
61 29.5% /home/h4ad/.asdf/installs/nodejs/12.22.12/bin/node
6 9.8% /home/h4ad/.asdf/installs/nodejs/12.22.12/bin/node
2 33.3% LazyCompile: ~readPackage internal/modules/cjs/loader.js:231:21
2 100.0% LazyCompile: ~readPackageScope internal/modules/cjs/loader.js:262:26
1 50.0% LazyCompile: ~trySelf internal/modules/cjs/loader.js:383:17
1 50.0% LazyCompile: ~Module._extensions..js internal/modules/cjs/loader.js:1008:37
2 33.3% LazyCompile: ~Module._findPath internal/modules/cjs/loader.js:436:28
2 100.0% LazyCompile: ~Module._resolveFilename internal/modules/cjs/loader.js:731:35
2 100.0% LazyCompile: ~Module._load internal/modules/cjs/loader.js:648:24
1 16.7% LazyCompile: ~stat internal/modules/cjs/loader.js:123:14
1 100.0% LazyCompile: ~tryFile internal/modules/cjs/loader.js:326:17
1 100.0% LazyCompile: ~tryExtensions internal/modules/cjs/loader.js:342:23
1 16.7% LazyCompile: ~realpathSync fs.js:1568:22
1 100.0% LazyCompile: ~toRealPath internal/modules/cjs/loader.js:335:20
1 100.0% LazyCompile: ~tryFile internal/modules/cjs/loader.js:326:17
5 8.2% LazyCompile: ~toRealPath internal/modules/cjs/loader.js:335:20
4 80.0% LazyCompile: ~tryFile internal/modules/cjs/loader.js:326:17
4 100.0% LazyCompile: ~tryExtensions internal/modules/cjs/loader.js:342:23
3 75.0% LazyCompile: ~Module._findPath internal/modules/cjs/loader.js:436:28
1 25.0% LazyCompile: ~tryPackage internal/modules/cjs/loader.js:279:20
1 20.0% LazyCompile: ~Module._findPath internal/modules/cjs/loader.js:436:28
1 100.0% LazyCompile: ~resolveMainPath internal/modules/run_main.js:8:25
1 100.0% LazyCompile: ~executeUserEntryPoint internal/modules/run_main.js:53:31
5 8.2% LazyCompile: *log /home/h4ad/Projects/opensource/performance-test-nestjs/test-performance/dist/perf/better-console-logger.service.js:47:8
4 80.0% LazyCompile: *log /home/h4ad/Projects/opensource/performance-test-nestjs/test-performance/dist/perf/better-logger.service.js:52:8
4 100.0% Eval: ~<anonymous> /home/h4ad/Projects/opensource/performance-test-nestjs/test-performance/dist/perf/perf-better-logger.js:1:1
4 100.0% LazyCompile: ~Module._compile internal/modules/cjs/loader.js:953:37
1 20.0% LazyCompile: *<anonymous> /home/h4ad/Projects/opensource/performance-test-nestjs/test-performance/dist/perf/perf-better-logger.js:1:1
1 100.0% LazyCompile: ~Module._compile internal/modules/cjs/loader.js:953:37
1 100.0% LazyCompile: ~Module._extensions..js internal/modules/cjs/loader.js:1008:37
Source
And the CPU profiling now looks like:
And the time to perform the log looks consistent between NodeJS environments.
perf-better-nodejs12.cpuprofile.zip
perf-better-nodejs16.cpuprofile.zip
perf-better-nodejs19.cpuprofile.zip
Finally, about the performance improvements, this is the result running on NodeJS 16:
Logger x 7,127 ops/sec ยฑ1.55% (87 runs sampled)
BetterLogger x 60,055 ops/sec ยฑ1.90% (65 runs sampled)
Console x 133,689 ops/sec ยฑ1.14% (90 runs sampled)
Console is just console.log
.
An improvement of 8x in the performance when logging.
I didn't make any breaking changes in the logs, but if we change from Intl.DateTimeFormat
API to just new Date().toISOString()
, the benchmark will look like:
Logger x 7,165 ops/sec ยฑ1.80% (80 runs sampled)
BetterLogger x 79,513 ops/sec ยฑ2.74% (62 runs sampled)
Console x 140,275 ops/sec ยฑ1.61% (88 runs sampled)
So let me know if worth to introduce some breaking changes just to have better performance when logging.
To reproduce all those tests, see this gist: https://gist.github.com/H4ad/da838dfc33b2060504ca980644d804b5
Does this PR introduce a breaking change?
Other information