+10-20% child creation, +7-8% basic/child logging, JSON output fix, sub-child loggers

[davidmarkclements]

fixes #20
closes #19

Summary:

• child loggers of child loggers as many as you want with close to zero overhead
• 10-20% speed improvement in child creation
• 7-8% improvement in basic logging and child logging
• important JSON output fix (child logger omits commas, leading to malformed json #20)
• improves express-pino-logger both requests per second and throughput by 15%

child creation shows speed improvements of between 10%-20%:

benchmarks/childCreation.js - old

benchPinoCreation_10000: 417ms
benchBunyanCreation_10000: 1345ms
benchBoleCreation_10000: 1584ms
benchPinoCreation_10000: 384ms
benchBunyanCreation_10000: 1277ms
benchBoleCreation_10000: 1572ms

benchmarks/childCreation.js - new

benchPinoCreation_10000: 362ms
benchBunyanCreation_10000: 1291ms
benchBoleCreation_10000: 1547ms
benchPinoCreation_10000: 338ms
benchBunyanCreation_10000: 1275ms
benchBoleCreation_10000: 1527ms

child logging benchmarks consistently showed a 7% speed up (basic benchmarks show this also)

benchmarks/child.js - old

benchBunyanObj_10000: 1254ms
benchPinoChild_10000: 353ms
benchBoleChild_10000: 1484ms
benchBunyanObj_10000: 1207ms
benchPinoChild_10000: 339ms
benchBoleChild_10000: 1460ms

benchmarks/child.js - new

benchBunyanObj_10000: 1260ms
benchPinoChild_10000: 329ms
benchBoleChild_10000: 1498ms
benchBunyanObj_10000: 1216ms
benchPinoChild_10000: 316ms
benchBoleChild_10000: 1473ms

sub-child loggers zero overhead

(also tested with children of children of children, same, no perceivable impact)

benchmarks/child-child.js

benchBunyanChildChild_10000: 1358ms
benchPinoChildChild_10000: 326ms
benchBunyanChildChild_10000: 1314ms
benchPinoChildChild_10000: 317ms

basic benchmarks consistently show a 7-8% speed up

benchmarks/basic.js - old

benchBunyan_10000: 1060ms
benchWinston_10000: 1825ms
benchBole_10000: 1642ms
benchPino_10000: 286ms
benchBunyan_10000: 1061ms
benchWinston_10000: 1718ms
benchBole_10000: 1590ms
benchPino_10000: 287ms

benchmarks/basic.js - new

benchBunyan_10000: 1192ms
benchWinston_10000: 1909ms
benchBole_10000: 1547ms
benchPino_10000: 264ms
benchBunyan_10000: 1085ms
benchWinston_10000: 1793ms
benchBole_10000: 1508ms
benchPino_10000: 260ms

object benchmarks roughly the same

multiple runs showed some differences but not conclusive enough to call it

multi arg benchmarks are about the same

express-pino-logger raw server benchmark 15% speed increase:

old

Running 10s test @ http://localhost:3000
  2 threads and 100 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     8.38ms    1.39ms  44.50ms   95.83%
    Req/Sec     6.02k   491.46     6.42k    91.00%
  119742 requests in 10.00s, 12.68MB read
Requests/sec:  11972.03
Transfer/sec:      1.27MB

New

Running 10s test @ http://localhost:3000
  2 threads and 100 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     7.14ms    1.25ms  42.43ms   97.29%
    Req/Sec     7.06k   557.69     7.53k    95.05%
  142014 requests in 10.10s, 15.03MB read
Requests/sec:  14060.12
Transfer/sec:      1.49MB

[mcollina]

👍 to be released as 2.0.0.

[mcollina]

The example and the README needs fixing, because it won't work anymore.

[davidmarkclements]

good point d27d9c5

[mcollina]

Awesome. LGTM and release as 2.0.0

[davidmarkclements]

just made a slight alteration, it doesn't come with any perf hit so we're good

the alteration is to make sure that the bindings of childs child are added to the json output after the parent, not before. This can be important in the case of a key clash between parent and child, particularly if we want pino to work as a drop in replacement for bunyan

for example, prior to the change in f8e7e09, we'd have this situation

> pino.child({a: 'property'}).child({a: 'prop'}).info('howdy')
{"pid":95469,"hostname":"MacBook-Pro-3.home","level":30,"msg":"howdy","time":1459533782032,"a":"prop","a":"property","v":1}

When you JSON.parse that the a keys' value will be "property" - (this is the value as set in the parent). In bunyan, the same scenario will result in JSON output with a single property (rather than the dupe property which we're accepting for perf reasons), with value corresponding to "prop" (e.g. the last child). So now we've changed output to do:

{"pid":95469,"hostname":"MacBook-Pro-3.home","level":30,"msg":"howdy","time":1459533782032,"a":"property","a":"prop","v":1}

So a JSON.parse (or, i.e. when we run a log file through pino -t) will lead to the same result as bunyan.

[mcollina]

Nice!
Il giorno ven 1 apr 2016 alle 20:09 David Mark Clements <
notifications@github.com> ha scritto:

just made a slight alteration, it doesn't come with any perf hit so we're
good

the alteration is to make sure that the bindings of childs child are added
to the json output after the parent, not before. This can be important
in the case of a key clash between parent and child, particularly if we
want pino to work as a drop in replacement for bunyan

for example, prior to the change in f8e7e09
f8e7e09,
we'd have this situation

pino.child({a: 'property'}).child({a: 'prop'}).info('howdy')
{"pid":95469,"hostname":"MacBook-Pro-3.home","level":30,"msg":"howdy","time":1459533782032,"a":"prop","a":"property","v":1}

When you JSON.parse that the a keys' value will be "property" - (this is
the value as set in the parent). In bunyan, the same scenario will result
in JSON output with a single property (rather than the dupe property which
we're accepting for perf reasons), with value corresponding to "prop" (e.g.
the last child). So now we've changed output to do:

{"pid":95469,"hostname":"MacBook-Pro-3.home","level":30,"msg":"howdy","time":1459533782032,"a":"property","a":"prop","v":1}

So a JSON.parse (or, i.e. when we run a log file through pino -t) will
lead to the same result as bunyan.

—
You are receiving this because you commented.

Reply to this email directly or view it on GitHub
#21 (comment)

[davidmarkclements]

squashed into single v2 commit, once ci checks have passed, I'll merge and then publish

[davidmarkclements]

v2.0.0 published

[jsumners]

Awesome. Thank you again.

[github-actions]

This pull request has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.