Performance improvements #80

nokome · 2021-01-11T00:14:38Z

I was recently evaluating whether we should continue to maintain Logga, or instead switch to using someone else's logging library. I decided that Logga has a useful combination of features that other libraries do not, and that we should indeed maintain it (but perhaps improve aspects).

As part of that evaluation I implemented some benchmarks and noticed that Logga had poor performance relative to other loggers:

bole x 667,896 ops/sec ±0.35% (93 runs sampled)
bunyan x 243,104 ops/sec ±0.27% (89 runs sampled)
logga x 28,811 ops/sec ±0.18% (97 runs sampled)
log4js x 155,397 ops/sec ±0.21% (96 runs sampled)
loglevel x 299,655 ops/sec ±0.38% (95 runs sampled)
pino x 664,888 ops/sec ±0.18% (94 runs sampled)
winston x 232,827 ops/sec ±4.53% (81 runs sampled)

It turned out that this was due to automatic stack generation feature (done for logged errors which are not passed an error). After removal of this "feature", performance was at least comparable to others:

bole x 657,008 ops/sec ±0.90% (93 runs sampled)
bunyan x 250,412 ops/sec ±0.27% (94 runs sampled)
logga x 253,980 ops/sec ±0.58% (97 runs sampled)
log4js x 143,212 ops/sec ±0.96% (93 runs sampled)
loglevel x 284,880 ops/sec ±0.39% (96 runs sampled)
pino x 671,490 ops/sec ±0.40% (93 runs sampled)
winston x 216,877 ops/sec ±5.55% (78 runs sampled)

I continued on the optimization train (see commits for details) until I got performance on par with the fastest of the other libraries:

bole x 793,786 ops/sec ±0.42% (92 runs sampled)
bunyan x 270,705 ops/sec ±0.41% (91 runs sampled)
logga x 798,245 ops/sec ±0.30% (94 runs sampled)
log4js x 213,667 ops/sec ±0.30% (92 runs sampled)
loglevel x 598,083 ops/sec ±0.37% (95 runs sampled)
pino x 696,967 ops/sec ±0.51% (92 runs sampled)
winston x 235,126 ops/sec ±6.26% (74 runs sampled)

Some time in the future I'd like to do some changes to the API and further optimizations may be possible along side those.

codecov-io · 2021-01-11T00:16:35Z

Codecov Report

Merging #80 (8fa458a) into master (29eca54) will decrease coverage by 0.61%.
The diff coverage is 96.00%.

@@            Coverage Diff             @@
##           master      #80      +/-   ##
==========================================
- Coverage   98.92%   98.30%   -0.62%     
==========================================
  Files           1        1              
  Lines          93      118      +25     
  Branches       39       53      +14     
==========================================
+ Hits           92      116      +24     
  Misses          1        1              
- Partials        0        1       +1

Impacted Files	Coverage Δ
index.ts	`98.30% <96.00%> (-0.62%)`	⬇️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 29eca54...8fa458a. Read the comment docs.

Before this Logga was ALOT slower than other logging libraries: bole x 667,896 ops/sec ±0.35% (93 runs sampled) bunyan x 243,104 ops/sec ±0.27% (89 runs sampled) logga x 28,811 ops/sec ±0.18% (97 runs sampled) log4js x 155,397 ops/sec ±0.21% (96 runs sampled) loglevel x 299,655 ops/sec ±0.38% (95 runs sampled) pino x 664,888 ops/sec ±0.18% (94 runs sampled) winston x 232,827 ops/sec ±4.53% (81 runs sampled) After, it was comparable: bole x 657,008 ops/sec ±0.90% (93 runs sampled) bunyan x 250,412 ops/sec ±0.27% (94 runs sampled) logga x 253,980 ops/sec ±0.58% (97 runs sampled) log4js x 143,212 ops/sec ±0.96% (93 runs sampled) loglevel x 284,880 ops/sec ±0.39% (96 runs sampled) pino x 671,490 ops/sec ±0.40% (93 runs sampled) winston x 216,877 ops/sec ±5.55% (78 runs sampled)

Before: logga x 256,339 ops/sec ±0.39% (341 runs sampled) After: logga x 393,670 ops/sec ±0.11% (344 runs sampled)

Similar to `bole`: the `time` property can be a timestamp or a string. Before logga x 402,553 ops/sec ±0.17% (592 runs sampled) After logga x 469,130 ops/sec ±0.11% (593 runs sampled)

Before: logga x 469,130 ops/sec ±0.11% (593 runs sampled) After: logga x 763,432 ops/sec ±0.18% (591 runs sampled)

Appears to have minor performance benefits but perhaps more importantly reduces the amount of code. Before: logga x 763,432 ops/sec ±0.18% (591 runs sampled) After: logga x 792,303 ops/sec ±0.12% (591 runs sampled)

alex-ketch

Thanks for this @nokome, the speed improvements look fantastic! 🏎💨
I've left a couple comments below, but also had a question regarding the upgrade process for consuming packages/apps. Would they require changes during update?

alex-ketch · 2021-01-12T18:26:57Z

index.ts

+  const name = '_logga'
+  if (name in root) {
+    // istanbul ignore next
+    // @ts-ignore


It would be better if we extended the global/Window type definition instead, for correctness as well as avoiding having to repeatedly use ignore statements like on line 70.

Would you be able to do that please?

done. I've made the global _logga an optional, to force checking its existence when someone tries to use it.
Feel free to suggest changes, or merge this PR at your leisure @nokome

Thanks! Will merge now.

alex-ketch · 2021-01-12T18:34:18Z

package.json

+    "benchmark": "2.1.4",
+    "bole": "4.0.0",
+    "bunyan": "1.8.15",
    "jest": "26.6.3",
+    "log4js": "6.3.0",
+    "loglevel": "1.7.1",
    "microbundle": "0.13.0",
+    "pino": "6.10.0",
    "ts-jest": "26.4.4",
    "typedoc": "0.20.14",
-    "typescript": "4.1.3"
+    "typescript": "4.1.3",
+    "winston": "3.3.3"


I would prefer not to commit all the various logging libraries to the project. I think just having the baseline numbers as you've documented in the PR comment is enough to compare against.
There are several downsides of having them in here, but the primary desire for me would be to reduce the potential for conflicting package dependencies (especially painful with type definitions), as well as overhead in keeping things up to date.

Agreed (and comment expected :)). I'll remove them and just add a comment to the benchmark.js about installing them.

nokome · 2021-01-12T20:22:11Z

...but also had a question regarding the upgrade process for consuming packages/apps. Would they require changes during update?

The API has not changed, only the internals, so no, changes should not be necessary. Regardless, this is a big change so I think it warrants a major version number

# [4.0.0](v3.0.1...v4.0.0) (2021-01-13) * Merge pull request #80 from stencila/perf ([fb9b270](fb9b270)), closes [#80](#80) ### Bug Fixes * **Escaping:** Remove unecessary branch ([2708f16](2708f16)) ### Performance Improvements * **Benchmarks:** Add a higher precision benchmark ([ab3e1d9](ab3e1d9)) * **Benchmarks:** Add benchmarking script ([ffbbcc2](ffbbcc2)) * **Benchmarks:** Use plain string messages ([503ce1a](503ce1a)) * **Deps:** Remove benmarking dependencies from package.json ([8fa458a](8fa458a)) * **Errors:** Remove automatic error stack generation ([2bd2aae](2bd2aae)) * **Fast time:** Add a fastTime option ([7259dba](7259dba)) * **Handlers:** Use a global singleton, rather than event bus ([5e20c8c](5e20c8c)) * **Output:** Use template strings rather than JSON.stringify ([e33e2f3](e33e2f3)) * **Output:** Write to process.stderr directly ([5d4db3b](5d4db3b)) ### BREAKING CHANGES * Mostly internal performance improvements but given the scale of changes labeling as a breaking change to trigger a major release.

stencila-ci · 2021-01-13T04:31:41Z

🎉 This PR is included in version 4.0.0 🎉

The release is available on:

Your semantic-release bot 📦🚀

nokome requested a review from alex-ketch January 11, 2021 00:14

nokome force-pushed the perf branch from 5610b30 to d6a4dca Compare January 11, 2021 00:15

nokome added 15 commits January 11, 2021 14:11

perf(Benchmarks): Add benchmarking script

ffbbcc2

chore(Formatting): Add JS files

4d43a91

perf(Benchmarks): Add a higher precision benchmark

ab3e1d9

perf(Output): Write to process.stderr directly

5d4db3b

Before: logga x 256,339 ops/sec ±0.39% (341 runs sampled) After: logga x 393,670 ops/sec ±0.11% (344 runs sampled)

perf(Fast time): Add a fastTime option

7259dba

Similar to `bole`: the `time` property can be a timestamp or a string. Before logga x 402,553 ops/sec ±0.17% (592 runs sampled) After logga x 469,130 ops/sec ±0.11% (593 runs sampled)

perf(Output): Use template strings rather than JSON.stringify

e33e2f3

Before: logga x 469,130 ops/sec ±0.11% (593 runs sampled) After: logga x 763,432 ops/sec ±0.18% (591 runs sampled)

perf(Benchmarks): Use plain string messages

503ce1a

perf(Handlers): Use a global singleton, rather than event bus

5e20c8c

Appears to have minor performance benefits but perhaps more importantly reduces the amount of code. Before: logga x 763,432 ops/sec ±0.18% (591 runs sampled) After: logga x 792,303 ops/sec ±0.12% (591 runs sampled)

test(Benchmarks): Use derp on higher precision suite as well

8f8df41

refactor(Output): Localize output code

c1268cf

chore(*): Linting

56de3cc

test(*): Add tests

9166037

chore(Deps): Fix merge conflicts; update Bunyan

bcc434c

test(*): Place ts-ignore on correct line

5ac5197

nokome force-pushed the perf branch from 7b93c3c to 5ac5197 Compare January 11, 2021 01:15

fix(Escaping): Remove unecessary branch

2708f16

alex-ketch reviewed Jan 12, 2021

View reviewed changes

perf(Deps): Remove benmarking dependencies from package.json

8fa458a

alex-ketch force-pushed the perf branch from 0580740 to a714815 Compare January 12, 2021 23:03

refactor(TS): Add type definitions for global variables

43f208e

alex-ketch force-pushed the perf branch from a714815 to 43f208e Compare January 12, 2021 23:04

nokome merged commit fb9b270 into master Jan 12, 2021

nokome deleted the perf branch January 12, 2021 23:13

stencila-ci added the released label Jan 13, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Performance improvements #80

Performance improvements #80

nokome commented Jan 11, 2021 •

edited

Loading

codecov-io commented Jan 11, 2021 •

edited

Loading

alex-ketch left a comment

alex-ketch Jan 12, 2021

nokome Jan 12, 2021

alex-ketch Jan 12, 2021

nokome Jan 12, 2021

alex-ketch Jan 12, 2021

nokome Jan 12, 2021

nokome commented Jan 12, 2021

stencila-ci commented Jan 13, 2021

Performance improvements #80

Performance improvements #80

Conversation

nokome commented Jan 11, 2021 • edited Loading

codecov-io commented Jan 11, 2021 • edited Loading

Codecov Report

alex-ketch left a comment

Choose a reason for hiding this comment

alex-ketch Jan 12, 2021

Choose a reason for hiding this comment

nokome Jan 12, 2021

Choose a reason for hiding this comment

alex-ketch Jan 12, 2021

Choose a reason for hiding this comment

nokome Jan 12, 2021

Choose a reason for hiding this comment

alex-ketch Jan 12, 2021

Choose a reason for hiding this comment

nokome Jan 12, 2021

Choose a reason for hiding this comment

nokome commented Jan 12, 2021

stencila-ci commented Jan 13, 2021

nokome commented Jan 11, 2021 •

edited

Loading

codecov-io commented Jan 11, 2021 •

edited

Loading