http: fix incorrect headersTimeout measurement - #30184
Conversation
Sorry, something went wrong.
There was a problem hiding this comment.
my understanding was that onMessageBegin will be called when the parser starts parsing a new request's headers.
Sorry, something went wrong.
There was a problem hiding this comment.
So when the parsing starts we capture when it started.
Sorry, something went wrong.
There was a problem hiding this comment.
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.
Sorry, something went wrong.
There was a problem hiding this comment.
will it affect performance? Not sure if there is a better way. An extra callback will be invoked for every request
Sorry, something went wrong.
There was a problem hiding this comment.
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.
Sorry, something went wrong.
There was a problem hiding this comment.
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.
Sorry, something went wrong.
|
CI: https://ci.nodejs.org/job/node-test-pull-request/26257/ |
Sorry, something went wrong.
|
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 ]
}
|
Sorry, something went wrong.
|
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 |
Sorry, something went wrong.
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. |
Sorry, something went wrong.
|
Perhaps there is some other way to fix the bug? without adding a new callback? |
Sorry, something went wrong.
|
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 |
Sorry, something went wrong.
mcollina
left a comment
There was a problem hiding this comment.
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.
Sorry, something went wrong.
Trott
left a comment
There was a problem hiding this comment.
LGTM although I'd prefer reviews from more http experts. @nodejs/http
Sorry, something went wrong.
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.
Sorry, something went wrong.
Sorry, something went wrong.
Sorry, something went wrong.
|
test.parallel/test-http-highwatermark is failing consistently on Windows with this change. |
Sorry, something went wrong.
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 ... |
Sorry, something went wrong.
|
@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. |
Sorry, something went wrong.
|
History for that test https://github.com/nodejs/node/commits/201fbdcbb675f4d1c24acda8889f456079ce4236/test/parallel/test-http-highwatermark.js |
Sorry, something went wrong.
Sorry, something went wrong.
Sorry, something went wrong.
mcollina
left a comment
There was a problem hiding this comment.
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.
Sorry, something went wrong.
|
@mcollina I have no alternative implementation for this issue yet. If someone has any ideas, please share. |
Sorry, something went wrong.
|
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. |
Sorry, something went wrong.
|
cc @nodejs/tsc |
Sorry, something went wrong.
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
left a comment
There was a problem hiding this comment.
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.
Sorry, something went wrong.
|
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. |
Sorry, something went wrong.
|
@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)? |
Sorry, something went wrong.
|
One possible solution to take the sting out:
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. |
Sorry, something went wrong.
|
I have opened a PR with an alternative implementation where the time spent parsing headers is tracked by the parser: #32329 |
Sorry, something went wrong.
Sounds like anything that will meet approval from others will be a fair bit different. I can re-review if this changes.
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