http: fix incorrect headersTimeout measurement #30184

OrKoN · 2019-10-30T22:52:29Z

For keep-alive connections, the headersTimeout may fire during subsequent requests
because the measurement was reset after a request and not before a request.

Fixes: #27363

Checklist

make -j4 test (UNIX), or vcbuild test (Windows) passes
tests and/or benchmarks are included
commit message follows commit guidelines

OrKoN · 2019-10-30T22:53:15Z

lib/_http_common.js

@@ -160,6 +161,7 @@ const parsers = new FreeList('parsers', 1000, function parsersCb() {
  parser[kOnHeadersComplete] = parserOnHeadersComplete;
  parser[kOnBody] = parserOnBody;
  parser[kOnMessageComplete] = parserOnMessageComplete;
+  parser[kOnMessageBegin] = null;


my understanding was that onMessageBegin will be called when the parser starts parsing a new request's headers.

OrKoN · 2019-10-30T22:53:50Z

lib/_http_server.js

@@ -520,11 +519,17 @@ function socketOnData(server, socket, parser, state, d) {
  onParserExecuteCommon(server, socket, parser, state, ret, d);
 }

+function onParserMessageBegin(parser) {
+  // We are starting to wait for the headers.
+  parser.parsingHeadersStart = nowDate();


So when the parsing starts we capture when it started.

I guess it's out of scope for this PR, but why are we depending on Date.now() for these things instead of the HR timer? What if a big NTP-sync shift happens during intervals like this? It could have a profound impact on how things run.

OrKoN · 2019-10-30T22:56:07Z

src/node_http_parser.cc

+    Local<Value> cb = obj->Get(env()->context(),
+                               kOnMessageBegin).ToLocalChecked();
+
+    if (!cb->IsFunction())


will it affect performance? Not sure if there is a better way. An extra callback will be invoked for every request

OrKoN · 2019-10-30T22:58:05Z

test/parallel/test-http-slow-headers-keepalive-multiple-requests.js

@@ -0,0 +1,50 @@
+'use strict';


this test fails on master with a timeout, and it's based on the test cases mentioned in #27363 This PR attempts to fix the problem.

OrKoN · 2019-10-31T07:33:55Z

test/parallel/test-http-highwatermark.js

@@ -14,7 +14,7 @@ let requestReceived = 0;
 const server = http.createServer(function(req, res) {
  const id = ++requestReceived;
  const enoughToDrain = req.connection.writableHighWaterMark;
-  const body = 'x'.repeat(enoughToDrain * 100);
+  const body = 'x'.repeat(enoughToDrain * 200);


This is the single unrelated test that is failing. I saw in its history that it was fixed as a flaky in the past. It seems to fails again and I don't think that it's related to my changes.

nodejs-github-bot · 2019-10-31T12:55:10Z

CI: https://ci.nodejs.org/job/node-test-pull-request/26257/
Benchmark CI: https://ci.nodejs.org/view/Node.js%20benchmark/job/benchmark-node-micro-benchmarks/456/

OrKoN · 2019-11-01T09:38:59Z

There are failing tests. One of them is testing async_hooks. Before the change the list of activities looks like this:

  {
    uid: 10,
    type: 'TCPWRAP',
    triggerAsyncId: 2,
    handleIsObject: true,
    handle: TCP {
      reading: true,
      onconnection: null,
      _consumed: true,
      [Symbol(owner)]: [Socket],
      [Symbol(handle_onclose)]: [Function (anonymous)]
    },
    init: [ 8595043 ],
    before: [ 14816332 ],
    after: [ 14877986 ],
    destroy: [ 15073587 ]
  },
  {
    uid: 11,
    type: 'HTTPINCOMINGMESSAGE',
    triggerAsyncId: 10,
    handleIsObject: true,
    handle: HTTPServerAsyncResource {
      type: 'HTTPINCOMINGMESSAGE',
      socket: [Socket]
    },
    init: [ 8962860 ],
    before: [ 10346086, 11629159, 11906853 ],
    after: [ 11619794, 11901012, 12064742 ],
    destroy: [ 15071548 ]
  },
  {
    uid: 12,
    type: 'Timeout',
    triggerAsyncId: 10,
    handleIsObject: true,
    handle: Timeout {
      _idleTimeout: 73,
      _idlePrev: [TimersList],
      _idleNext: [TimersList],
      _idleStart: 61,
      _onTimeout: [Function: resetCache],
      _timerArgs: undefined,
      _repeat: null,
      _destroyed: false,
      [Symbol(refed)]: false,
      [Symbol(asyncId)]: 12,
      [Symbol(triggerId)]: 10
    },
    init: [ 9244603 ]
  }

After the change there is an additional tick object:

{
    uid: 10,
    type: 'TCPWRAP',
    triggerAsyncId: 2,
    handleIsObject: true,
    handle: TCP {
      reading: true,
      onconnection: null,
      _consumed: true,
      [Symbol(owner)]: [Socket],
      [Symbol(handle_onclose)]: [Function (anonymous)]
    },
    init: [ 7490860 ],
    before: [ 13020576 ],
    after: [ 13081163 ],
    destroy: [ 13278055 ]
  },
  {
    uid: 11,
    type: 'HTTPINCOMINGMESSAGE',
    triggerAsyncId: 10,
    handleIsObject: true,
    handle: HTTPServerAsyncResource {
      type: 'HTTPINCOMINGMESSAGE',
      socket: [Socket]
    },
    init: [ 7815015 ],
    before: [ 8551340, 9055408, 10158585, 10406175 ],
    after: [ 9043147, 10151736, 10400572, 10518668 ],
    destroy: [ 13276166 ]
  },
  {
    uid: 12,
    type: 'TickObject',
    triggerAsyncId: 10,
    handleIsObject: true,
    handle: {
      callback: [Function: resume_],
      args: [Array],
      [Symbol(asyncId)]: 12,
      [Symbol(triggerAsyncId)]: 10
    },
    init: [ 7856302 ],
    before: [ 7924714 ],
    after: [ 7961489 ],
    destroy: [ 8456876 ]
  },
  {
    uid: 13,
    type: 'Timeout',
    triggerAsyncId: 11,
    handleIsObject: true,
    handle: Timeout {
      _idleTimeout: 47,
      _idlePrev: [TimersList],
      _idleNext: [TimersList],
      _idleStart: 62,
      _onTimeout: [Function: resetCache],
      _timerArgs: undefined,
      _repeat: null,
      _destroyed: false,
      [Symbol(refed)]: false,
      [Symbol(asyncId)]: 13,
      [Symbol(triggerId)]: 11
    },
    init: [ 8809985 ]
  }

OrKoN · 2019-11-01T10:23:28Z

It looks like the usage of async functions affects what async hooks report in other tests. It seems those tests capture arbitrary side effects which are internal implementation of http server. Adding the following line back should fix some of broken tests: dc9fc6a although it's not needed for the logic anymore

addaleax · 2019-11-03T12:45:52Z

Benchmark CI results

                                                                                               confidence improvement accuracy (*)    (**)   (***)
 http/bench-parser.js n=100000 len=16                                                                         -2.15 %       ±2.26%  ±3.02%  ±3.95%
 http/bench-parser.js n=100000 len=32                                                                         -0.00 %       ±4.33%  ±5.79%  ±7.58%
 http/bench-parser.js n=100000 len=4                                                                   **    -11.21 %       ±6.77%  ±9.06% ±11.92%
 http/bench-parser.js n=100000 len=8                                                                  ***     -5.55 %       ±2.58%  ±3.46%  ±4.55%
 http/check_invalid_header_char.js n=1000000 input=''                                                         -2.83 %       ±5.81%  ±7.73% ±10.06%
 http/check_invalid_header_char.js n=1000000 input='\177'                                                      1.89 %       ±7.91% ±10.54% ±13.76%
 http/check_invalid_header_char.js n=1000000 input='1'                                                        -3.35 %       ±6.64%  ±8.84% ±11.50%
 http/check_invalid_header_char.js n=1000000 input='20091'                                             **      7.36 %       ±5.44%  ±7.28%  ±9.54%
 http/check_invalid_header_char.js n=1000000 input='close'                                              *      6.22 %       ±5.65%  ±7.52%  ±9.79%
 http/check_invalid_header_char.js n=1000000 input='en-US'                                                     4.07 %       ±8.05% ±10.73% ±14.01%
 http/check_invalid_header_char.js n=1000000 input='foo\\nbar'                                                 0.96 %       ±4.96%  ±6.60%  ±8.60%
 http/check_invalid_header_char.js n=1000000 input='group_acmeair'                                            -1.36 %       ±4.76%  ±6.33%  ±8.24%
 http/check_invalid_header_char.js n=1000000 input='gzip'                                                     -2.37 %       ±5.72%  ±7.62%  ±9.93%
 http/check_invalid_header_char.js n=1000000 input='keep-alive'                                               -3.38 %       ±4.83%  ±6.43%  ±8.37%
 http/check_invalid_header_char.js n=1000000 input='LONG_AND_INVALID'                                         -2.48 %       ±2.64%  ±3.52%  ±4.58%
 http/check_invalid_header_char.js n=1000000 input='private'                                                   3.46 %       ±5.26%  ±7.02%  ±9.17%
 http/check_invalid_header_char.js n=1000000 input='SAMEORIGIN'                                                1.69 %       ±4.41%  ±5.86%  ±7.63%
 http/check_invalid_header_char.js n=1000000 input='Sat, 07 May 2016 16:54:48 GMT'                             0.95 %       ±4.19%  ±5.57%  ±7.25%
 http/check_invalid_header_char.js n=1000000 input='text/html; charset=utf-8'                                  3.03 %       ±3.75%  ±5.00%  ±6.51%
 http/check_invalid_header_char.js n=1000000 input='text/plain'                                                1.16 %       ±4.39%  ±5.85%  ±7.61%
 http/check_invalid_header_char.js n=1000000 input='\\t\\t\\t\\t\\t\\t\\t\\t\\t\\tFoo bar baz'                 2.74 %       ±4.18%  ±5.57%  ±7.27%
 http/check_invalid_header_char.js n=1000000 input='中文呢'                                                   -3.18 %       ±5.61%  ±7.47%  ±9.72%
 http/check_is_http_token.js n=1000000 key=':'                                                                -0.04 %       ±4.72%  ±6.28%  ±8.19%
 http/check_is_http_token.js n=1000000 key='((((())))'                                                  *     -5.43 %       ±5.30%  ±7.07%  ±9.22%
 http/check_is_http_token.js n=1000000 key='@@'                                                                0.20 %       ±6.30%  ±8.39% ±10.93%
 http/check_is_http_token.js n=1000000 key='Accept-Ranges'                                                    -6.32 %       ±8.10% ±10.87% ±14.33%
 http/check_is_http_token.js n=1000000 key=':alternate-protocol'                                               0.76 %       ±7.21%  ±9.60% ±12.49%
 http/check_is_http_token.js n=1000000 key='alternate-protocol:'                                               2.35 %       ±4.22%  ±5.61%  ±7.30%
 http/check_is_http_token.js n=1000000 key='alternate-protocol'                                               -2.33 %       ±3.44%  ±4.58%  ±5.97%
 http/check_is_http_token.js n=1000000 key='alt-svc'                                                          -0.37 %       ±6.94%  ±9.26% ±12.11%
 http/check_is_http_token.js n=1000000 key='Cache-Control'                                                    -6.99 %       ±7.84% ±10.51% ±13.84%
 http/check_is_http_token.js n=1000000 key='Connection'                                                       -6.74 %       ±8.11% ±10.89% ±14.37%
 http/check_is_http_token.js n=1000000 key='Content-Encoding'                                                  1.22 %       ±3.93%  ±5.23%  ±6.81%
 http/check_is_http_token.js n=1000000 key='content-length'                                                   -3.65 %       ±8.02% ±10.75% ±14.13%
 http/check_is_http_token.js n=1000000 key='Content-Location'                                                 -2.42 %       ±3.63%  ±4.83%  ±6.29%
 http/check_is_http_token.js n=1000000 key='content-type'                                                     -6.27 %       ±8.01% ±10.73% ±14.12%
 http/check_is_http_token.js n=1000000 key='Content-Type'                                                     -1.91 %       ±7.93% ±10.63% ±13.98%
 http/check_is_http_token.js n=1000000 key='date'                                                              4.59 %       ±9.42% ±12.59% ±16.48%
 http/check_is_http_token.js n=1000000 key='ETag'                                                              2.10 %       ±6.53%  ±8.70% ±11.35%
 http/check_is_http_token.js n=1000000 key='Expires'                                                          -0.31 %       ±6.06%  ±8.06% ±10.49%
 http/check_is_http_token.js n=1000000 key='Keep-Alive'                                                       -0.40 %       ±4.12%  ±5.48%  ±7.14%
 http/check_is_http_token.js n=1000000 key='Last-Modified'                                                    -4.57 %       ±8.08% ±10.81% ±14.20%
 http/check_is_http_token.js n=1000000 key='location'                                                         -4.92 %       ±8.68% ±11.61% ±15.23%
 http/check_is_http_token.js n=1000000 key='server'                                                           -3.54 %       ±4.49%  ±5.97%  ±7.78%
 http/check_is_http_token.js n=1000000 key='Server'                                                           -3.39 %       ±4.75%  ±6.32%  ±8.23%
 http/check_is_http_token.js n=1000000 key='status'                                                           -5.06 %       ±6.54%  ±8.73% ±11.41%
 http/check_is_http_token.js n=1000000 key='TCN'                                                        *     -4.81 %       ±4.57%  ±6.11%  ±8.02%
 http/check_is_http_token.js n=1000000 key='Transfer-Encoding'                                                -3.49 %       ±7.76% ±10.40% ±13.69%
 http/check_is_http_token.js n=1000000 key='Vary'                                                              1.24 %       ±5.97%  ±7.95% ±10.35%
 http/check_is_http_token.js n=1000000 key='version'                                                           0.69 %       ±5.28%  ±7.03%  ±9.16%
 http/check_is_http_token.js n=1000000 key='x-frame-options'                                                  -3.85 %       ±7.88% ±10.56% ±13.91%
 http/check_is_http_token.js n=1000000 key='x-xss-protection'                                                 -2.93 %       ±7.87% ±10.54% ±13.85%
 http/check_is_http_token.js n=1000000 key='中文呢'                                                            2.35 %       ±5.82%  ±7.76% ±10.12%
 http/chunked.js c=100 len=1 n=16 benchmarker='wrk'                                                           -0.24 %       ±0.53%  ±0.71%  ±0.92%
 http/chunked.js c=100 len=1 n=1 benchmarker='wrk'                                                             0.25 %       ±0.32%  ±0.43%  ±0.56%
 http/chunked.js c=100 len=1 n=4 benchmarker='wrk'                                                            -0.12 %       ±0.33%  ±0.44%  ±0.57%
 http/chunked.js c=100 len=1 n=8 benchmarker='wrk'                                                             0.05 %       ±0.27%  ±0.36%  ±0.47%
 http/chunked.js c=100 len=256 n=16 benchmarker='wrk'                                                         -0.39 %       ±0.64%  ±0.85%  ±1.11%
 http/chunked.js c=100 len=256 n=1 benchmarker='wrk'                                                    *     -0.29 %       ±0.26%  ±0.35%  ±0.45%
 http/chunked.js c=100 len=256 n=4 benchmarker='wrk'                                                          -0.01 %       ±0.28%  ±0.37%  ±0.48%
 http/chunked.js c=100 len=256 n=8 benchmarker='wrk'                                                          -0.31 %       ±0.38%  ±0.51%  ±0.66%
 http/chunked.js c=100 len=64 n=16 benchmarker='wrk'                                                          -0.07 %       ±0.59%  ±0.79%  ±1.02%
 http/chunked.js c=100 len=64 n=1 benchmarker='wrk'                                                           -0.03 %       ±0.26%  ±0.35%  ±0.45%
 http/chunked.js c=100 len=64 n=4 benchmarker='wrk'                                                           -0.03 %       ±0.36%  ±0.48%  ±0.62%
 http/chunked.js c=100 len=64 n=8 benchmarker='wrk'                                                            0.09 %       ±0.33%  ±0.44%  ±0.57%
 http/client-request-body.js method='end' len=1024 type='asc' dur=5                                           -6.01 %       ±7.31%  ±9.73% ±12.68%
 http/client-request-body.js method='end' len=1024 type='buf' dur=5                                           -3.90 %       ±7.54% ±10.03% ±13.05%
 http/client-request-body.js method='end' len=1024 type='utf' dur=5                                           -0.30 %       ±7.56% ±10.06% ±13.09%
 http/client-request-body.js method='end' len=256 type='asc' dur=5                                            -0.46 %       ±7.64% ±10.16% ±13.23%
 http/client-request-body.js method='end' len=256 type='buf' dur=5                                             1.34 %       ±7.52% ±10.01% ±13.03%
 http/client-request-body.js method='end' len=256 type='utf' dur=5                                            -1.22 %       ±7.50%  ±9.98% ±12.99%
 http/client-request-body.js method='end' len=32 type='asc' dur=5                                              1.77 %       ±6.41%  ±8.52% ±11.10%
 http/client-request-body.js method='end' len=32 type='buf' dur=5                                              4.92 %       ±7.93% ±10.55% ±13.74%
 http/client-request-body.js method='end' len=32 type='utf' dur=5                                              0.44 %       ±6.00%  ±7.99% ±10.41%
 http/client-request-body.js method='write' len=1024 type='asc' dur=5                                         -0.07 %       ±7.74% ±10.30% ±13.40%
 http/client-request-body.js method='write' len=1024 type='buf' dur=5                                         -1.95 %       ±7.41%  ±9.86% ±12.83%
 http/client-request-body.js method='write' len=1024 type='utf' dur=5                                         -2.80 %       ±7.90% ±10.52% ±13.70%
 http/client-request-body.js method='write' len=256 type='asc' dur=5                                          -5.05 %       ±7.35%  ±9.77% ±12.72%
 http/client-request-body.js method='write' len=256 type='buf' dur=5                                           2.63 %       ±8.35% ±11.11% ±14.48%
 http/client-request-body.js method='write' len=256 type='utf' dur=5                                          -4.38 %       ±6.89%  ±9.17% ±11.94%
 http/client-request-body.js method='write' len=32 type='asc' dur=5                                     *      7.96 %       ±7.49%  ±9.98% ±13.01%
 http/client-request-body.js method='write' len=32 type='buf' dur=5                                           -3.90 %       ±6.08%  ±8.09% ±10.54%
 http/client-request-body.js method='write' len=32 type='utf' dur=5                                           -6.48 %       ±7.35%  ±9.79% ±12.74%
 http/cluster.js c=500 len=102400 type='buffer' benchmarker='wrk'                                             -1.28 %       ±3.38%  ±4.50%  ±5.87%
 http/cluster.js c=500 len=102400 type='bytes' benchmarker='wrk'                                              -2.12 %       ±3.62%  ±4.82%  ±6.27%
 http/cluster.js c=500 len=1024 type='buffer' benchmarker='wrk'                                               -2.33 %       ±3.34%  ±4.45%  ±5.79%
 http/cluster.js c=500 len=1024 type='bytes' benchmarker='wrk'                                                -2.15 %       ±3.81%  ±5.07%  ±6.60%
 http/cluster.js c=500 len=4 type='buffer' benchmarker='wrk'                                                  -1.31 %       ±3.27%  ±4.35%  ±5.67%
 http/cluster.js c=500 len=4 type='bytes' benchmarker='wrk'                                                    0.03 %       ±3.45%  ±4.59%  ±5.99%
 http/cluster.js c=50 len=102400 type='buffer' benchmarker='wrk'                                              -1.13 %       ±3.43%  ±4.57%  ±5.95%
 http/cluster.js c=50 len=102400 type='bytes' benchmarker='wrk'                                                1.59 %       ±3.42%  ±4.56%  ±5.95%
 http/cluster.js c=50 len=1024 type='buffer' benchmarker='wrk'                                                -2.26 %       ±3.27%  ±4.36%  ±5.69%
 http/cluster.js c=50 len=1024 type='bytes' benchmarker='wrk'                                                  0.97 %       ±3.16%  ±4.20%  ±5.47%
 http/cluster.js c=50 len=4 type='buffer' benchmarker='wrk'                                                   -2.35 %       ±3.47%  ±4.61%  ±6.00%
 http/cluster.js c=50 len=4 type='bytes' benchmarker='wrk'                                                    -2.09 %       ±3.40%  ±4.52%  ±5.89%
 http/create-clientrequest.js e=1 arg='options' url='idn'                                               *    -10.30 %      ±10.22% ±13.71% ±18.09%
 http/create-clientrequest.js e=1 arg='options' url='long'                                                    -1.63 %       ±8.01% ±10.66% ±13.90%
 http/create-clientrequest.js e=1 arg='options' url='wpt'                                                      1.65 %       ±8.95% ±11.91% ±15.50%
 http/create-clientrequest.js e=1 arg='string' url='idn'                                                      -1.22 %       ±8.58% ±11.42% ±14.88%
 http/create-clientrequest.js e=1 arg='string' url='long'                                                     -1.66 %       ±8.67% ±11.54% ±15.03%
 http/create-clientrequest.js e=1 arg='string' url='wpt'                                                      -0.34 %      ±10.93% ±14.57% ±19.04%
 http/create-clientrequest.js e=1 arg='URL' url='idn'                                                         -4.04 %       ±7.84% ±10.44% ±13.59%
 http/create-clientrequest.js e=1 arg='URL' url='long'                                                        -2.61 %       ±7.27%  ±9.71% ±12.71%
 http/create-clientrequest.js e=1 arg='URL' url='wpt'                                                         -2.99 %      ±10.89% ±14.52% ±18.98%
 http/end-vs-write-end.js method='end' c=100 len=1048576 type='asc' benchmarker='wrk'                         -0.64 %       ±4.56%  ±6.07%  ±7.90%
 http/end-vs-write-end.js method='end' c=100 len=1048576 type='buf' benchmarker='wrk'                          1.31 %       ±5.35%  ±7.13%  ±9.28%
 http/end-vs-write-end.js method='end' c=100 len=1048576 type='utf' benchmarker='wrk'                          3.68 %       ±4.08%  ±5.42%  ±7.06%
 http/end-vs-write-end.js method='end' c=100 len=131072 type='asc' benchmarker='wrk'                           1.29 %       ±2.63%  ±3.51%  ±4.58%
 http/end-vs-write-end.js method='end' c=100 len=131072 type='buf' benchmarker='wrk'                           0.52 %       ±3.40%  ±4.53%  ±5.90%
 http/end-vs-write-end.js method='end' c=100 len=131072 type='utf' benchmarker='wrk'                   **     -4.07 %       ±2.97%  ±3.96%  ±5.20%
 http/end-vs-write-end.js method='end' c=100 len=262144 type='asc' benchmarker='wrk'                           0.95 %       ±2.17%  ±2.89%  ±3.77%
 http/end-vs-write-end.js method='end' c=100 len=262144 type='buf' benchmarker='wrk'                          -1.70 %       ±5.02%  ±6.68%  ±8.70%
 http/end-vs-write-end.js method='end' c=100 len=262144 type='utf' benchmarker='wrk'                           1.23 %       ±2.86%  ±3.81%  ±4.96%
 http/end-vs-write-end.js method='end' c=100 len=65536 type='asc' benchmarker='wrk'                           -2.31 %       ±3.46%  ±4.60%  ±5.99%
 http/end-vs-write-end.js method='end' c=100 len=65536 type='buf' benchmarker='wrk'                           -4.51 %       ±5.60%  ±7.45%  ±9.71%
 http/end-vs-write-end.js method='end' c=100 len=65536 type='utf' benchmarker='wrk'                           -0.92 %       ±2.91%  ±3.87%  ±5.04%
 http/end-vs-write-end.js method='write' c=100 len=1048576 type='asc' benchmarker='wrk'                       -2.09 %       ±4.32%  ±5.75%  ±7.49%
 http/end-vs-write-end.js method='write' c=100 len=1048576 type='buf' benchmarker='wrk'                       -1.02 %       ±5.67%  ±7.55%  ±9.82%
 http/end-vs-write-end.js method='write' c=100 len=1048576 type='utf' benchmarker='wrk'                       -0.05 %       ±4.96%  ±6.60%  ±8.59%
 http/end-vs-write-end.js method='write' c=100 len=131072 type='asc' benchmarker='wrk'                         1.05 %       ±3.98%  ±5.31%  ±6.94%
 http/end-vs-write-end.js method='write' c=100 len=131072 type='buf' benchmarker='wrk'                        -0.50 %       ±3.69%  ±4.93%  ±6.44%
 http/end-vs-write-end.js method='write' c=100 len=131072 type='utf' benchmarker='wrk'                         1.30 %       ±3.98%  ±5.30%  ±6.91%
 http/end-vs-write-end.js method='write' c=100 len=262144 type='asc' benchmarker='wrk'                         3.63 %       ±4.13%  ±5.51%  ±7.19%
 http/end-vs-write-end.js method='write' c=100 len=262144 type='buf' benchmarker='wrk'                        -2.39 %       ±4.56%  ±6.07%  ±7.91%
 http/end-vs-write-end.js method='write' c=100 len=262144 type='utf' benchmarker='wrk'                        -0.48 %       ±4.53%  ±6.03%  ±7.87%
 http/end-vs-write-end.js method='write' c=100 len=65536 type='asc' benchmarker='wrk'                         -0.47 %       ±3.78%  ±5.02%  ±6.54%
 http/end-vs-write-end.js method='write' c=100 len=65536 type='buf' benchmarker='wrk'                         -0.93 %       ±5.55%  ±7.40%  ±9.65%
 http/end-vs-write-end.js method='write' c=100 len=65536 type='utf' benchmarker='wrk'                          1.04 %       ±3.72%  ±4.95%  ±6.44%
 http/headers.js len=100 n=1000 benchmarker='wrk'                                                       *      3.05 %       ±2.53%  ±3.38%  ±4.43%
 http/headers.js len=100 n=10 benchmarker='wrk'                                                               -2.32 %       ±4.17%  ±5.55%  ±7.22%
 http/headers.js len=1 n=1000 benchmarker='wrk'                                                                0.75 %       ±1.62%  ±2.15%  ±2.80%
 http/headers.js len=1 n=10 benchmarker='wrk'                                                           *     -4.32 %       ±3.67%  ±4.88%  ±6.36%

Be aware that when doing many comparisons the risk of a false-positive
result increases. In this case there are 132 comparisons, you can thus
expect the following amount of false-positive results:
  6.60 false positives, when considering a   5% risk acceptance (*, **, ***),
  1.32 false positives, when considering a   1% risk acceptance (**, ***),
  0.13 false positives, when considering a 0.1% risk acceptance (***)

I think the only relevant ones are

 http/bench-parser.js n=100000 len=4        **    -11.21 %       ±6.77%  ±9.06% ±11.92%
 http/bench-parser.js n=100000 len=8       ***     -5.55 %       ±2.58%  ±3.46%  ±4.55%

but I’m not sure if we need to do anything about those if this fixes an actual bug and doesn’t affect the benchmarks for HTTP altogether.

OrKoN · 2019-11-04T08:32:59Z

Perhaps there is some other way to fix the bug? without adding a new callback?

BridgeAR · 2019-12-25T20:04:45Z

The performance should not be worried about too much as long as this fixes a bug. The performance could probably be improved later on.

@nodejs/http @nodejs/http2 @nodejs/streams @ronag PTAL

mcollina

lgtm, it would be good to have a backport PR for 12.x and 10.x as there is still the old http_parser there.

Trott

LGTM although I'd prefer reviews from more http experts. @nodejs/http

nodejs-github-bot · 2020-01-05T00:52:48Z

CI: https://ci.nodejs.org/job/node-test-pull-request/28212/

src/node_http_parser.cc

nodejs-github-bot · 2020-01-12T01:09:05Z

CI: https://ci.nodejs.org/job/node-test-pull-request/28382/

nodejs-github-bot · 2020-01-12T02:34:31Z

CI: https://ci.nodejs.org/job/node-test-pull-request/28386/

Trott · 2020-01-12T03:32:41Z

test.parallel/test-http-highwatermark is failing consistently on Windows with this change.

Trott · 2020-01-12T03:34:14Z

18:35:43 not ok 238 parallel/test-http-highwatermark
18:35:43   ---
18:35:43   duration_ms: 0.244
18:35:43   severity: fail
18:35:43   exitcode: 1
18:35:43   stack: |-
18:35:43     Mismatched <anonymous> function calls. Expected exactly 1, actual 0.
18:35:43         at Object.mustCall (C:\workspace\node-test-binary-windows-js-suites\node\test\common\index.js:325:10)
18:35:43         at Server.<anonymous> (C:\workspace\node-test-binary-windows-js-suites\node\test\parallel\test-http-highwatermark.js:21:41)
18:35:43         at Server.emit (events.js:321:20)
18:35:43         at parserOnIncoming (_http_server.js:782:12)
18:35:43         at HTTPParser.parserOnHeadersComplete (_http_common.js:117:17)
18:35:43     Mismatched <anonymous> function calls. Expected exactly 1, actual 0.
18:35:43         at Object.mustCall (C:\workspace\node-test-binary-windows-js-suites\node\test\common\index.js:325:10)
18:35:43         at Server.<anonymous> (C:\workspace\node-test-binary-windows-js-suites\node\test\parallel\test-http-highwatermark.js:28:43)
18:35:43         at Server.emit (events.js:321:20)
18:35:43         at parserOnIncoming (_http_server.js:782:12)
18:35:43         at HTTPParser.parserOnHeadersComplete (_http_common.js:117:17)
18:35:43   ...

OrKoN · 2020-01-12T18:20:10Z

@Trott It looks like a flaky test for me. It's been fixed in the past as being flaky and I had to change it because it was failing for me. I will remove that change to see if it passes after that.

OrKoN · 2020-01-12T18:23:44Z

History for that test https://github.com/nodejs/node/commits/201fbdcbb675f4d1c24acda8889f456079ce4236/test/parallel/test-http-highwatermark.js

nodejs-github-bot · 2020-02-03T02:52:46Z

CI: https://ci.nodejs.org/job/node-test-pull-request/28884/

nodejs-github-bot · 2020-03-11T07:18:55Z

CI: https://ci.nodejs.org/job/node-test-pull-request/29720/

mcollina

Can we avoid calling from C++ to JavaScript? This will affect performance.

I would prefer if we did not regress on the performance of our http implementation quite a bit, and it's one of our core metrics.

OrKoN · 2020-03-11T10:13:28Z

@mcollina I have no alternative implementation for this issue yet. If someone has any ideas, please share.

mcollina · 2020-03-11T13:24:52Z

I think we might try keeping the current time in C++ instead and implementing that logic there instead.

If we decide we want to land this anyway as it is, let's open a new issue to track the perf regression.

mcollina · 2020-03-11T13:25:06Z

cc @nodejs/tsc

For keep-alive connections, the headersTimeout may fire during subsequent request because the measurement was reset after a request and not before a request. Fixes: nodejs#27363

jasnell

The time tracking absolutely should remain at the c++ level. It's not cost free but uv_hrtime() should be used. If the timestamps need to be exposed to JavaScript then an aliased array can be used.

OrKoN · 2020-03-17T14:58:57Z

I want to point out that time-tracking was in JS already. This PR only adds onMessageBegin callback to the parser to be able to reset the var at the right time. I am looking into moving time-tracking code into C++ atm.

OrKoN · 2020-03-17T15:21:43Z

@mcollina I got a partially working implementation where the time is being tracked in node_http_parser.cc using uv_hrtime. Is node_http_parser.cc an appropriate place for that? I don't find any other timers in the parser code at the moment. Currently, I check the time in OnStreamRead before kOnExecute is invoked. What would be the best way to trigger a timeout error from here? Should I add a new callback (e.g., kOnTimeout)?

bnoordhuis · 2020-03-19T12:46:07Z

One possible solution to take the sting out:

Start a watchdog thread that, in a loop, sleeps for ~1000 ms, then atomically updates a timestamp.
Have the main thread read that timestamp (atomically) and turn it into a Date object or whatever.

That makes the timestamp collection basically free from the POV of the main thread because the cost is paid by the watchdog thread.

We already have a watchdog thread that can be repurposed/extended for this.

I can put up a prototype if people feel the above is a good way forward.

OrKoN · 2020-03-19T14:20:36Z

I have opened a PR with an alternative implementation where the time spent parsing headers is tracked by the parser: #32329

Sounds like anything that will meet approval from others will be a fair bit different. I can re-review if this changes.

OrKoN · 2020-04-02T12:53:40Z

Closed in favor of #32329

nodejs-github-bot added c++ Issues and PRs that require attention from people who are familiar with C++. http Issues or PRs related to the http subsystem. http_parser Issues and PRs related to the HTTP Parser dependency or the http_parser binding. labels Oct 30, 2019

OrKoN commented Oct 30, 2019

View reviewed changes

OrKoN force-pushed the fix-headers-timeout branch from 4018ecf to 4fc9095 Compare October 30, 2019 23:04

OrKoN commented Oct 31, 2019

View reviewed changes

BridgeAR requested review from mcollina, apapirovski, addaleax and indutny December 25, 2019 20:05

mcollina approved these changes Dec 26, 2019

View reviewed changes

Trott previously approved these changes Dec 31, 2019

View reviewed changes

BridgeAR added the author ready PRs that have at least one approval, no pending requests for changes, and a CI started. label Jan 2, 2020

This comment has been minimized.

Sign in to view

addaleax removed the author ready PRs that have at least one approval, no pending requests for changes, and a CI started. label Jan 5, 2020

addaleax reviewed Jan 5, 2020

View reviewed changes

src/node_http_parser.cc Outdated Show resolved Hide resolved

Trott removed the author ready PRs that have at least one approval, no pending requests for changes, and a CI started. label Jan 12, 2020

OrKoN mentioned this pull request Jan 25, 2020

test: fix flaky test-http-highwatermark #17949

Closed

3 tasks

mcollina requested changes Mar 11, 2020

View reviewed changes

OrKoN added 5 commits March 17, 2020 13:59

http: fix incorrect headersTimeout measurement

f7281ca

For keep-alive connections, the headersTimeout may fire during subsequent request because the measurement was reset after a request and not before a request. Fixes: nodejs#27363

test: fix flaky test-http-highwatermark

8cfd1b8

http: add nowDate() to async scope

aa83993

http: use nullptr to fix win build

845d4bb

http: revert flaky test fix

01c2228

OrKoN force-pushed the fix-headers-timeout branch from b51887b to 01c2228 Compare March 17, 2020 13:01

jasnell requested changes Mar 17, 2020

View reviewed changes

OrKoN mentioned this pull request Mar 17, 2020

http: fix incorrect headersTimeout measurement (alt) #32329

Closed

4 tasks

OrKoN closed this Apr 2, 2020

OrKoN deleted the fix-headers-timeout branch April 2, 2020 12:53

http: fix incorrect headersTimeout measurement #30184

http: fix incorrect headersTimeout measurement #30184

Conversation

OrKoN commented Oct 30, 2019 • edited Loading

Checklist

OrKoN Oct 30, 2019

Choose a reason for hiding this comment

OrKoN Oct 30, 2019

Choose a reason for hiding this comment

ronkorving Jan 6, 2020

Choose a reason for hiding this comment

OrKoN Oct 30, 2019

Choose a reason for hiding this comment

OrKoN Oct 30, 2019 • edited Loading

Choose a reason for hiding this comment

OrKoN Oct 31, 2019 • edited Loading

Choose a reason for hiding this comment

nodejs-github-bot commented Oct 31, 2019 • edited by addaleax Loading

OrKoN commented Nov 1, 2019

OrKoN commented Nov 1, 2019 • edited Loading

addaleax commented Nov 3, 2019 • edited Loading

OrKoN commented Nov 4, 2019

BridgeAR commented Dec 25, 2019 • edited Loading

mcollina left a comment

Choose a reason for hiding this comment

Trott left a comment

Choose a reason for hiding this comment

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

nodejs-github-bot commented Jan 5, 2020

nodejs-github-bot commented Jan 12, 2020

nodejs-github-bot commented Jan 12, 2020

Trott commented Jan 12, 2020

Trott commented Jan 12, 2020

OrKoN commented Jan 12, 2020

OrKoN commented Jan 12, 2020 • edited Loading

nodejs-github-bot commented Feb 3, 2020

nodejs-github-bot commented Mar 11, 2020

mcollina left a comment

Choose a reason for hiding this comment

OrKoN commented Mar 11, 2020

mcollina commented Mar 11, 2020

mcollina commented Mar 11, 2020

jasnell left a comment

Choose a reason for hiding this comment

OrKoN commented Mar 17, 2020 • edited Loading

OrKoN commented Mar 17, 2020

bnoordhuis commented Mar 19, 2020

OrKoN commented Mar 19, 2020

OrKoN commented Apr 2, 2020

OrKoN commented Oct 30, 2019 •

edited

Loading

OrKoN Oct 30, 2019 •

edited

Loading

OrKoN Oct 31, 2019 •

edited

Loading

nodejs-github-bot commented Oct 31, 2019 •

edited by addaleax

Loading

OrKoN commented Nov 1, 2019 •

edited

Loading

addaleax commented Nov 3, 2019 •

edited

Loading

BridgeAR commented Dec 25, 2019 •

edited

Loading

OrKoN commented Jan 12, 2020 •

edited

Loading

OrKoN commented Mar 17, 2020 •

edited

Loading