Fix #42 #43

jsumners · 2017-12-02T23:00:17Z

edger-reqs branch:

##### http-ndjson-equivalent-server.js #####

Running 5s test @ http://localhost:3000
100 connections with 10 pipelining factor

Stat         Avg    Stdev   Max
Latency (ms) 9.92   30.01   282
Req/Sec      9869.6 660.97  10215
Bytes/Sec    1.1 MB 85.2 kB 1.18 MB

49k requests in 5s, 5.48 MB read

##### http-ndjson-minimal-server.js #####

Running 5s test @ http://localhost:3000
100 connections with 10 pipelining factor

Stat         Avg     Stdev   Max
Latency (ms) 8.88    26.83   249
Req/Sec      11032.8 803.97  11599
Bytes/Sec    1.23 MB 98.3 kB 1.31 MB

55k requests in 5s, 6.12 MB read

##### no-log-server.js #####

Running 5s test @ http://localhost:3000
100 connections with 10 pipelining factor

Stat         Avg     Stdev  Max
Latency (ms) 3.89    11.74  122
Req/Sec      25195.2 993.21 26095
Bytes/Sec    2.79 MB 128 kB 3.01 MB

126k requests in 5s, 14 MB read

##### pino-extreme-server.js #####

Running 5s test @ http://localhost:3000
100 connections with 10 pipelining factor

Stat         Avg     Stdev   Max
Latency (ms) 6.12    18.41   147
Req/Sec      16008.8 336.03  16279
Bytes/Sec    1.79 MB 26.2 kB 1.84 MB

80k requests in 5s, 8.88 MB read

##### pino-server.js #####

Running 5s test @ http://localhost:3000
100 connections with 10 pipelining factor

Stat         Avg     Stdev  Max
Latency (ms) 6.75    20.31  168
Req/Sec      14533.6 557.24 15079
Bytes/Sec    1.62 MB 49 kB  1.7 MB

73k requests in 5s, 8.07 MB read

master branch:

##### http-ndjson-equivalent-server.js #####

Running 5s test @ http://localhost:3000
100 connections with 10 pipelining factor

Stat         Avg    Stdev   Max
Latency (ms) 9.92   30.05   280
Req/Sec      9868   753.84  10311
Bytes/Sec    1.1 MB 85.2 kB 1.18 MB

49k requests in 5s, 5.48 MB read

##### http-ndjson-minimal-server.js #####

Running 5s test @ http://localhost:3000
100 connections with 10 pipelining factor

Stat         Avg     Stdev   Max
Latency (ms) 8.92    27.09   231
Req/Sec      10981.6 1003.59 11823
Bytes/Sec    1.22 MB 112 kB  1.38 MB

55k requests in 5s, 6.09 MB read

##### no-log-server.js #####

Running 5s test @ http://localhost:3000
100 connections with 10 pipelining factor

Stat         Avg     Stdev  Max
Latency (ms) 3.88    11.77  137
Req/Sec      25211.2 981.49 26191
Bytes/Sec    2.79 MB 128 kB 3.01 MB

126k requests in 5s, 14 MB read

##### pino-extreme-server.js #####

Running 5s test @ http://localhost:3000
100 connections with 10 pipelining factor

Stat         Avg     Stdev   Max
Latency (ms) 6.03    18.12   151
Req/Sec      16264.8 310.96  16447
Bytes/Sec    1.79 MB 26.2 kB 1.84 MB

81k requests in 5s, 9.03 MB read

##### pino-server.js #####

Running 5s test @ http://localhost:3000
100 connections with 10 pipelining factor

Stat         Avg     Stdev   Max
Latency (ms) 6.83    20.56   165
Req/Sec      14348   287.56  14535
Bytes/Sec    1.59 MB 26.2 kB 1.64 MB

72k requests in 5s, 7.96 MB read

coveralls · 2017-12-02T23:02:04Z

Coverage increased (+0.2%) to 98.333% when pulling 765c6b9 on edgar-reqs into c0851b5 on master.

jsumners · 2017-12-03T17:34:23Z

I think this is going to be semver major. Custom req serializers no longer directly receive the whole request. They must access it via the req.raw property.

Given this, I think it is best to:

Merge this PR
Move the standard serializers out of pino and into pino-http (see Remove headers from standard http serializers pino#265)

That means pino will also see a major release. Not optimal, but the longer we wait the worse it will be.

coveralls · 2017-12-03T17:41:32Z

Coverage increased (+0.2%) to 98.333% when pulling 626eede on edgar-reqs into c0851b5 on master.

coveralls · 2017-12-03T17:41:33Z

Coverage increased (+0.2%) to 98.333% when pulling 626eede on edgar-reqs into c0851b5 on master.

coveralls · 2017-12-03T17:41:33Z

Coverage increased (+0.2%) to 98.333% when pulling 626eede on edgar-reqs into c0851b5 on master.

mcollina · 2017-12-03T17:46:33Z

logger.js

+    Object.defineProperty(_req, 'raw', {
+      enumerable: false,
+      value: req
+    })


Adding a new property via defineProperty in a serializer (which is a hot-path) is definitely not a good idea perf-wise. We should transform asReqValue in a class, and attach this property to its prototype, and always memorize it internally through a Symbol.

I have updated the PR. I hope I have addressed your concern correctly.

jsumners · 2017-12-03T18:45:07Z

Benchmarks for commit 5aebe40:

##### http-ndjson-equivalent-server.js #####

Running 5s test @ http://localhost:3000
100 connections with 10 pipelining factor

Stat         Avg    Stdev   Max
Latency (ms) 9.98   30.23   273
Req/Sec      9808.8 744.08  10255
Bytes/Sec    1.1 MB 85.2 kB 1.18 MB

49k requests in 5s, 5.44 MB read

##### http-ndjson-minimal-server.js #####

Running 5s test @ http://localhost:3000
100 connections with 10 pipelining factor

Stat         Avg     Stdev   Max
Latency (ms) 8.86    26.8    242
Req/Sec      11066.4 822.95  11679
Bytes/Sec    1.24 MB 78.6 kB 1.31 MB

55k requests in 5s, 6.14 MB read

##### no-log-server.js #####

Running 5s test @ http://localhost:3000
100 connections with 10 pipelining factor

Stat         Avg     Stdev  Max
Latency (ms) 3.79    11.49  129
Req/Sec      25806.4 946.07 26543
Bytes/Sec    2.9 MB  105 kB 3.01 MB

129k requests in 5s, 14.3 MB read

##### pino-extreme-server.js #####

Running 5s test @ http://localhost:3000
100 connections with 10 pipelining factor

Stat         Avg     Stdev   Max
Latency (ms) 6.39    19.21   151
Req/Sec      15352.8 400.98  15751
Bytes/Sec    1.7 MB  52.4 kB 1.77 MB

77k requests in 5s, 8.52 MB read

##### pino-server.js #####

Running 5s test @ http://localhost:3000
100 connections with 10 pipelining factor

Stat         Avg     Stdev   Max
Latency (ms) 6.91    20.82   171
Req/Sec      14183.2 486.64  14527
Bytes/Sec    1.58 MB 52.4 kB 1.64 MB

71k requests in 5s, 7.87 MB read

coveralls · 2017-12-03T18:46:34Z

Coverage decreased (-1.0%) to 97.183% when pulling 5aebe40 on edgar-reqs into c0851b5 on master.

davidmarkclements · 2017-12-04T13:37:33Z

logger.js

+    writable: true,
+    value: ''
+  },
+  raw: {


at this point I fail to see the point of the symbol

@mcollina - thoughts?

It gives a free non-enumerable. While writing this I learned:

const proto = Object.create({}, { foo: { enumerable: false, writable: true, value: {} } }) const instance = Object.create(proto) console.log('%j', instance) // {} instance.foo = 'foo' console.log('%j', instance) // {"foo":"foo"}

no sure – but you'd get that without the symbol and the getter/setter

whats req.raw for btw... I saw it in the hapi-pino implementation as well - whats the reasoning

ah no no wait, you'd need a getter - but you could just return req

No, same thing happens with the getter and setter unless you wrap the object in a function with an enclosed variable to contain the value instead of set (val) { this._foo = val }.

As for req.raw, see comments hapijs/hapi-pino#34 (comment) and hapijs/hapi-pino#34 (comment)

See https://gist.github.com/jsumners/0a586bf6c3dcb835d692251347a0e730

davidmarkclements · 2017-12-04T13:57:40Z

test.js

@@ -303,3 +303,34 @@ test('does not crash when no request connection object', function (t) {
    res.end()
  }
 })
+


can we add a test for raw

coveralls · 2017-12-04T14:03:41Z

Coverage increased (+0.4%) to 98.592% when pulling 014c271 on edgar-reqs into c0851b5 on master.

coveralls · 2017-12-04T14:03:41Z

Coverage increased (+0.4%) to 98.592% when pulling 014c271 on edgar-reqs into c0851b5 on master.

coveralls · 2017-12-04T14:03:42Z

Coverage increased (+0.4%) to 98.592% when pulling 014c271 on edgar-reqs into c0851b5 on master.

jsumners · 2017-12-05T13:43:36Z

@mcollina @davidmarkclements opinions on #43 (comment)? Or is this PR not semver major?

davidmarkclements · 2017-12-05T13:58:32Z

I agree on major for pino-http

Even though I suggested removing serialisers from pino core I'm not sure I want to potentially break something someone is doing for the sake of purity

davidmarkclements · 2017-12-05T13:59:36Z

We need to check that Koa integration works with this as well, should do - but worth a check

jsumners · 2017-12-08T13:22:54Z

@davidmarkclements

mcollina · 2017-12-08T18:30:33Z

I think we should bite the bullet and do the same thing for res as well, so that we can stop depending on the standard res serializers.

mcollina

LGTM anyway

jsumners · 2017-12-08T18:37:44Z

@mcollina same PR or a different one?

mcollina · 2017-12-08T18:39:51Z

@jsumners up to you :).

Is this semver-minor or semver-major for you? If it's semver-major, then I would combine them in a single release.

jsumners · 2017-12-08T18:41:30Z

Both @davidmarkclements and I are of the opinion that this is semver-major.

mcollina · 2017-12-08T18:42:40Z

I would prefer to combine this with the change on res as well before releasing!

jsumners · 2017-12-08T18:58:47Z

@mcollina as you wish, it is done :)

mcollina

LGTM :D Thanks!

coveralls · 2017-12-08T19:01:37Z

Coverage increased (+0.6%) to 98.795% when pulling e5cfc82 on edgar-reqs into c0851b5 on master.

Fix #42

765c6b9

jsumners requested review from mcollina and davidmarkclements December 2, 2017 23:00

jsumners mentioned this pull request Dec 2, 2017

apply default serializer.req before using configured serializer.req hapijs/hapi-pino#34

Closed

Fix typo in test description

626eede

mcollina reviewed Dec 3, 2017

View reviewed changes

Use a V8 class for the internal request object

5aebe40

davidmarkclements reviewed Dec 4, 2017

View reviewed changes

Add test for req.raw

014c271

mcollina approved these changes Dec 8, 2017

View reviewed changes

Add response wrapper to match request wrapper

e5cfc82

mcollina approved these changes Dec 8, 2017

View reviewed changes

jsumners merged commit f91ce07 into master Dec 8, 2017

jsumners deleted the edgar-reqs branch December 8, 2017 19:02

benib mentioned this pull request Jan 2, 2018

wrap custom serializers hapijs/hapi-pino#42

Merged

jsumners mentioned this pull request Feb 20, 2018

How to serialize the whole object, not properties? pinojs/pino#362

Closed

Fix #42 #43

Fix #42 #43

Conversation

jsumners commented Dec 2, 2017

coveralls commented Dec 2, 2017 • edited Loading

jsumners commented Dec 3, 2017

coveralls commented Dec 3, 2017

coveralls commented Dec 3, 2017

coveralls commented Dec 3, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jsumners commented Dec 3, 2017

coveralls commented Dec 3, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

davidmarkclements Dec 4, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

coveralls commented Dec 4, 2017

coveralls commented Dec 4, 2017

coveralls commented Dec 4, 2017

jsumners commented Dec 5, 2017

davidmarkclements commented Dec 5, 2017

davidmarkclements commented Dec 5, 2017

jsumners commented Dec 8, 2017

mcollina commented Dec 8, 2017

mcollina left a comment

Choose a reason for hiding this comment

jsumners commented Dec 8, 2017

mcollina commented Dec 8, 2017

jsumners commented Dec 8, 2017

mcollina commented Dec 8, 2017

jsumners commented Dec 8, 2017

mcollina left a comment

Choose a reason for hiding this comment

coveralls commented Dec 8, 2017 • edited Loading

coveralls commented Dec 2, 2017 •

edited

Loading

coveralls commented Dec 3, 2017 •

edited

Loading

davidmarkclements Dec 4, 2017 •

edited

Loading

coveralls commented Dec 8, 2017 •

edited

Loading