async_hooks: don't reuse resource in HttpAgent when queued by puzpuzpuz · Pull Request #34439 · nodejs/node

puzpuzpuz · 2020-07-20T13:12:20Z

Checklist

This PR is a continuation of the http.Agent async resource reuse fix started in #27581. It deals with the case when a socket is not available immediately and, thus, the request is pushed into agent's queue.

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

lib/_http_agent.js

puzpuzpuz · 2020-07-20T13:15:48Z

@Flarna is it too much to ask you to review this one (as it seems to be related with #27581)?

puzpuzpuz · 2020-07-20T14:36:46Z

Pushed an additional test to verify http.Agent + ALS bundle, like it was in the bug report.

puzpuzpuz · 2020-07-21T07:09:29Z

@nodejs/async_hooks I'd appreciate some reviews here. 🙏🏻

vdeturckheim

LGTM - do we have a benchmark for this? It should not impact too much but still.

lib/_http_agent.js

puzpuzpuz · 2020-07-21T13:11:56Z

LGTM - do we have a benchmark for this? It should not impact too much but still.

I've checked existing benchmarks and the benchmark/http/client-request-body.js one may be the right fit for these changes, as it uses new http.Agent({ maxSockets: 1 }). I'll run it for this PR.

puzpuzpuz · 2020-07-21T15:00:39Z

Here is the benchmark/http/client-request-body.js benchmark result (https://ci.nodejs.org/view/Node.js%20benchmark/job/benchmark-node-micro-benchmarks/647):

17:56:08                                                                       confidence improvement accuracy (*)    (**)   (***)
17:56:08  http/client-request-body.js method='end' len=1024 type='asc' dur=5                   0.12 %       ±6.10%  ±8.12% ±10.57%
17:56:08  http/client-request-body.js method='end' len=1024 type='buf' dur=5            *     -6.37 %       ±5.97%  ±7.94% ±10.34%
17:56:08  http/client-request-body.js method='end' len=1024 type='utf' dur=5                  -5.08 %       ±6.43%  ±8.56% ±11.14%
17:56:08  http/client-request-body.js method='end' len=256 type='asc' dur=5                   -0.48 %       ±7.70% ±10.25% ±13.34%
17:56:08  http/client-request-body.js method='end' len=256 type='buf' dur=5                   -5.44 %       ±6.60%  ±8.79% ±11.44%
17:56:08  http/client-request-body.js method='end' len=256 type='utf' dur=5                   -3.62 %       ±6.58%  ±8.76% ±11.40%
17:56:08  http/client-request-body.js method='end' len=32 type='asc' dur=5              *     -8.07 %       ±6.11%  ±8.13% ±10.59%
17:56:08  http/client-request-body.js method='end' len=32 type='buf' dur=5              *     -6.99 %       ±5.93%  ±7.89% ±10.26%
17:56:08  http/client-request-body.js method='end' len=32 type='utf' dur=5                     2.44 %       ±6.35%  ±8.47% ±11.06%
17:56:08  http/client-request-body.js method='write' len=1024 type='asc' dur=5                -2.92 %       ±6.96%  ±9.26% ±12.05%
17:56:08  http/client-request-body.js method='write' len=1024 type='buf' dur=5                -4.82 %       ±6.09%  ±8.11% ±10.55%
17:56:08  http/client-request-body.js method='write' len=1024 type='utf' dur=5                -1.19 %       ±6.72%  ±8.94% ±11.65%
17:56:08  http/client-request-body.js method='write' len=256 type='asc' dur=5           *     -8.19 %       ±6.68%  ±8.89% ±11.57%
17:56:08  http/client-request-body.js method='write' len=256 type='buf' dur=5                  0.81 %       ±6.89%  ±9.17% ±11.93%
17:56:08  http/client-request-body.js method='write' len=256 type='utf' dur=5                 -0.51 %       ±6.03%  ±8.03% ±10.45%
17:56:08  http/client-request-body.js method='write' len=32 type='asc' dur=5                  -2.12 %       ±7.13%  ±9.49% ±12.36%
17:56:08  http/client-request-body.js method='write' len=32 type='buf' dur=5                  -1.29 %       ±6.14%  ±8.16% ±10.63%
17:56:08  http/client-request-body.js method='write' len=32 type='utf' dur=5                  -3.73 %       ±6.82%  ±9.09% ±11.85%
17:56:08 
17:56:08 Be aware that when doing many comparisons the risk of a false-positive
17:56:08 result increases. In this case there are 18 comparisons, you can thus
17:56:08 expect the following amount of false-positive results:
17:56:08   0.90 false positives, when considering a   5% risk acceptance (*, **, ***),
17:56:08   0.18 false positives, when considering a   1% risk acceptance (**, ***),
17:56:08   0.02 false positives, when considering a 0.1% risk acceptance (***)

puzpuzpuz · 2020-07-22T07:01:27Z

I've done another run of the benchmark and this time it gave slightly different results: https://ci.nodejs.org/view/Node.js%20benchmark/job/benchmark-node-micro-benchmarks/650

Looks like the benchmark involves a lot of jitter, yet it makes me thinking that there is no significant performance degradation introduced by this fix. After all, AsyncResource doesn't do a lot of operations when hooks are disabled.

nodejs-github-bot · 2020-07-23T08:20:46Z

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

Flarna · 2020-07-27T08:12:24Z

@Flarna is it too much to ask you to review this one (as it seems to be related with #27581)?

Sorry for my late response, I was on vacation. Will try to review soon.

puzpuzpuz · 2020-07-27T08:22:06Z

@Flarna no problem at all. Thanks for the update!

lib/_http_agent.js

test/async-hooks/test-http-agent-handle-reuse-parallel.js

puzpuzpuz · 2020-07-29T07:20:35Z

@Flarna I've noticed one more place where we might loose async context. I'm talking about Agent.removeSocket() method which may be called in .on('free') listener: https://github.com/nodejs/node/blob/master/lib/_http_agent.js#L162

removeSocket() method itself seems to be reading queued requests: https://github.com/nodejs/node/blob/master/lib/_http_agent.js#L426
and then it may execute the first suitable request on a newly created socket:
https://github.com/nodejs/node/blob/master/lib/_http_agent.js#L445

So, I wonder if I should wrap this.createSocket() call on L448 with restored AsyncResource (if the resource is present, of course). WDYT?

Flarna · 2020-07-29T10:57:23Z

@puzpuzpuz I'm not that deep into the HttpAgent flow. Maybe start by creating a test which reproduces the problem you think you found. If you fail it's maybe a code path which can't happen.

puzpuzpuz · 2020-07-29T11:12:33Z

@puzpuzpuz I'm not that deep into the HttpAgent flow. Maybe start by creating a test which reproduces the problem you think you found. If you fail it's maybe a code path which can't happen.

@Flarna yeah, I see. Then I'm going to double check the path and try to reproduce it with a test. Going to update this PR, if necessary, and notify the reviewers.

puzpuzpuz · 2020-07-30T14:51:14Z

@Flarna yeah, I see. Then I'm going to double check the path and try to reproduce it with a test. Going to update this PR, if necessary, and notify the reviewers.

Update. I've checked the code path and we should be ok with the fix, as the removeSocket() method to .on('free') listener invocation which in its turn restores the async context for the queued request.

Going to re-run CI tests and land the fix.

nodejs-github-bot · 2020-07-30T14:52:01Z

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

PR-URL: #34439 Fixes: #34401 Refs: #27581 Reviewed-By: Vladimir de Turckheim <[email protected]> Reviewed-By: Gerhard Stöbich <[email protected]>

puzpuzpuz · 2020-07-30T16:28:17Z

Landed in 019ea07

puzpuzpuz · 2020-07-30T16:29:36Z

@vdeturckheim @Flarna many thanks for your reviews!

PR-URL: #34439 Fixes: #34401 Refs: #27581 Reviewed-By: Vladimir de Turckheim <[email protected]> Reviewed-By: Gerhard Stöbich <[email protected]>

codebytere · 2020-11-03T04:18:14Z

Blocked on #32801

puzpuzpuz added http Issues or PRs related to the http subsystem. async_hooks Issues and PRs related to the async hooks subsystem. labels Jul 20, 2020

puzpuzpuz commented Jul 20, 2020

View reviewed changes

lib/_http_agent.js Outdated Show resolved Hide resolved

puzpuzpuz force-pushed the defect/async-resource-reused-in-http-agent branch from 7d9619c to ed432dc Compare July 20, 2020 14:34

vdeturckheim approved these changes Jul 21, 2020

View reviewed changes

lib/_http_agent.js Outdated Show resolved Hide resolved

puzpuzpuz force-pushed the defect/async-resource-reused-in-http-agent branch from ed432dc to de40cba Compare July 21, 2020 13:03

Flarna reviewed Jul 27, 2020

View reviewed changes

lib/_http_agent.js Outdated Show resolved Hide resolved

puzpuzpuz force-pushed the defect/async-resource-reused-in-http-agent branch from de40cba to 5548f89 Compare July 28, 2020 07:40

himself65 reviewed Jul 28, 2020

View reviewed changes

test/async-hooks/test-http-agent-handle-reuse-parallel.js Outdated Show resolved Hide resolved

async_hooks: don't reuse resource in HttpAgent when queued

2212e09

puzpuzpuz force-pushed the defect/async-resource-reused-in-http-agent branch from 5548f89 to 2212e09 Compare July 28, 2020 17:10

Flarna approved these changes Jul 28, 2020

View reviewed changes

puzpuzpuz added a commit that referenced this pull request Jul 30, 2020

async_hooks: don't reuse resource in HttpAgent when queued

019ea07

PR-URL: #34439 Fixes: #34401 Refs: #27581 Reviewed-By: Vladimir de Turckheim <[email protected]> Reviewed-By: Gerhard Stöbich <[email protected]>

puzpuzpuz closed this Jul 30, 2020

puzpuzpuz deleted the defect/async-resource-reused-in-http-agent branch July 30, 2020 16:28

codebytere pushed a commit that referenced this pull request Aug 5, 2020

async_hooks: don't reuse resource in HttpAgent when queued

14656e1

PR-URL: #34439 Fixes: #34401 Refs: #27581 Reviewed-By: Vladimir de Turckheim <[email protected]> Reviewed-By: Gerhard Stöbich <[email protected]>

codebytere mentioned this pull request Aug 10, 2020

v14.8.0 proposal #34704

Merged

codebytere added the backport-blocked-v12.x label Nov 3, 2020

puzpuzpuz mentioned this pull request Nov 19, 2020

AsyncLocalStorage does not work with http.Agent #34401

Closed

Uh oh!

Conversation

puzpuzpuz commented Jul 20, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Checklist

Uh oh!

Uh oh!

puzpuzpuz commented Jul 20, 2020

Uh oh!

puzpuzpuz commented Jul 20, 2020

Uh oh!

puzpuzpuz commented Jul 21, 2020

Uh oh!

vdeturckheim left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

puzpuzpuz commented Jul 21, 2020

Uh oh!

puzpuzpuz commented Jul 21, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

puzpuzpuz commented Jul 22, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

nodejs-github-bot commented Jul 23, 2020

Uh oh!

Flarna commented Jul 27, 2020

Uh oh!

puzpuzpuz commented Jul 27, 2020

Uh oh!

Uh oh!

Uh oh!

puzpuzpuz commented Jul 29, 2020

Uh oh!

Flarna commented Jul 29, 2020

Uh oh!

puzpuzpuz commented Jul 29, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

puzpuzpuz commented Jul 30, 2020

Uh oh!

nodejs-github-bot commented Jul 30, 2020

Uh oh!

puzpuzpuz commented Jul 30, 2020

Uh oh!

puzpuzpuz commented Jul 30, 2020

Uh oh!

codebytere commented Nov 3, 2020

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

6 participants

puzpuzpuz commented Jul 20, 2020 •

edited

Loading

puzpuzpuz commented Jul 21, 2020 •

edited

Loading

puzpuzpuz commented Jul 22, 2020 •

edited

Loading

puzpuzpuz commented Jul 29, 2020 •

edited

Loading