test: add uv threadpool congestion regression test #23099

gireeshpunathil · 2018-09-26T06:52:56Z

Validate that massive dns lookups do not block filesytem I/O (or any fast I/O for that matter).
Prior to libuv/libuv#1845 few back-to-back dns lookup were sufficient to engage libuv threadpool workers in a blocking manner, throttling other work items that need the pool. this test acts as a regression test for the same.

Start slow and fast I/Os together, and make sure fast I/O can complete in at least in 1/100th of time for slow I/O.

Refs: libuv/libuv#1845
Refs: #8436

Checklist

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

nodejs-github-bot · 2018-09-26T06:52:57Z

@gireeshpunathil build started: https://ci.nodejs.org/blue/organizations/jenkins/node-test-pull-request-lite-pipeline/detail/node-test-pull-request-lite-pipeline/1022/pipeline

Trott · 2018-09-26T12:24:36Z

This test fails without an internet connection so it probably needs to go in test/internet rather than test/sequential.

Here's what I get if I disconnect from the network:

$ tools/test.py test/sequential/test-uv-threadpool-schedule.js 
=== release test-uv-threadpool-schedule ===                    
Path: sequential/test-uv-threadpool-schedule
assert.js:349
    throw err;
    ^

AssertionError [ERR_ASSERTION]: fast I/O took longer to complete, actual: 10, expected: 0.57
    at GetAddrInfoReqWrap.dns.lookup.common.mustCall (/Users/trott/io.js/test/sequential/test-uv-threadpool-schedule.js:45:14)
    at GetAddrInfoReqWrap.callback (/Users/trott/io.js/test/common/index.js:349:15)
    at GetAddrInfoReqWrap.onlookup [as oncomplete] (dns.js:58:17)
Command: out/Release/node /Users/trott/io.js/test/sequential/test-uv-threadpool-schedule.js
[00:00|% 100|+   0|-   1]: Done  
$

cjihrig · 2018-09-26T12:32:41Z

This also seems like it will have the potential to be flakey when run on the CI.

thefourtheye · 2018-09-26T15:55:22Z

test/sequential/test-uv-threadpool-schedule.js

+  }));
+}
+
+fs.readFile(__filename, common.mustCall((e, d) => {


Unused variables.

@thefourtheye - removed, thanks.

thefourtheye · 2018-09-26T15:56:35Z

test/sequential/test-uv-threadpool-schedule.js

+  // We need to refresh the domain string everytime,
+  // otherwise the TCP stack that cache the previous lookup
+  // returns result from memory, breaking all our Math.
+  dns.lookup(`${randomDomain()}.com`, {}, common.mustCall((e, a, f) => {


Throw in an assert.ifError maybe?

sorry, didn't follow you - can you please elaborate? all these lookups are destined to fail, we are latching on the time they take for un-optimized full blown lookups (so as to maximize the threadpool worker thread's engagement)

thefourtheye · 2018-09-26T16:00:27Z

test/sequential/test-uv-threadpool-schedule.js

+for (let i = 0; i < slowIOmax; i++) {
+  // We need to refresh the domain string everytime,
+  // otherwise the TCP stack that cache the previous lookup
+  // returns result from memory, breaking all our Math.


In that case, using a base string and then keep incrementing an offset would guarantee that there will be no repetition in the domain names used, right? Because, the random numbers might repeat (even though odds of that happening is less)

thanks for the suggestion, followed your suggestion.

@thefourtheye - I just spotted a drawback of doing this: if you run the test back-to-back, it fails the second time onwards - for obvious reasons (the domain strings being static, they get resolved faster). I don't know if it affects our CI tests though.

thefourtheye · 2018-09-26T16:02:24Z

test/sequential/test-uv-threadpool-schedule.js

+function randomDomain() {
+  const d = Buffer.alloc(10);
+  for (let i = 0; i < 10; i++)
+    d[i] = 92 + (Math.round(Math.random() * 13247)) % 26;


Did you mean to use 97 ('a') instead of 92 ('\')?

removed the method altogether. (yes, I meant a , don't know how I kept it at 92. ;) )

gireeshpunathil · 2018-09-27T04:48:30Z

@Trott - moved this to internet folder. I didn't know the rules for placement; I see many tests that perform dns lookup on public websites in sequential folder, but looks like none of them are time sensitive.

@cjihrig - I acknowledge that the test is sensitive to response times. For that matter I took these precautions:

simplified the test by making only two most essential assertions (easy for spotting)
ideally the fastI/O should not take even 1/1000th of slowI/O (even those do not hold a dependency relation in any ways), but given the plurality of CI system types, I kept a conservative duration of 1/100th of that of slowI/O. If we relax it any further (either by increasing the dns lookup count or by reducing the expected ratio), I fear it violates the purpose of the test.
sprinkled comments abundantly so that if it fails one can easily reason out.

If you think any specific construct / logic is prone to flake, please let me know, I am happy to improve on it.

richardlau · 2018-09-27T05:01:21Z

test/internet/test-uv-threadpool-schedule.js

+  // We need to refresh the domain string everytime,
+  // otherwise the TCP stack that cache the previous lookup
+  // returns result from memory, breaking all our Math.
+  dns.lookup(`${randomDomain}${i}.com`, {}, common.mustCall(() => {


Does the test still work if we use one of the reserved TLDs (e.g. .test)? https://tools.ietf.org/html/rfc2606

- dns.lookup(`${randomDomain}${i}.com`, {}, common.mustCall(() => { + dns.lookup(`${randomDomain}${i}.test`, {}, common.mustCall(() => {

@richardlau - I tested with this change (if that is what you meant) and it still works. But what would be an advantage of it?

The reserved TLDs are specifically reserved to avoid conflicts with actual registered domain names, e.g. nonexistent0.com might exist in the future.

They can also avoid unnecessary load on the DNS servers, see https://tools.ietf.org/html/rfc6761 section 6.

@richardlau : ok - let me clarify: the purpose of the test is to engage (half of) the libuv threadpool workers as long as possible while making sure at least one thread is free and available to serve the file I/Os. So in that context, what we want is a list of domain names that are unique, and were unresolved earlier (resolved names are cached so retrieved faster than we wanted them to), existent or non-existent is not a consideration for the test. If the name is confusing, I can change it to unique0.com etc.

Am I missing anything?

If caching is an issue, we might need to generate domain names that are unique per-test-run, e.g. based on Date.now() or Math.random()?

yes (my first commit 1d0fcefec8a42b71166e572de14b308e1dc97e58) had it based on Math.random(). I guess I will re-instate that, thanks.

gireeshpunathil · 2018-09-28T07:00:58Z

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

Trott · 2018-09-30T16:43:46Z

I suppose pinging @nodejs/libuv to review may be appropriate here.

gireeshpunathil · 2018-09-30T17:07:39Z

thanks @Trott . Also cc @nodejs/testing ?

gireeshpunathil · 2018-10-04T06:36:59Z

re-instated the random domain function, else the test runs the risk of looking up previously resolved domain names and messing up with the time calculation.

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

gireeshpunathil · 2018-10-04T07:53:21Z

arm failure is unrelated:

03:20:28 not ok 1816 parallel/test-tls-generic-stream
03:20:28   ---
03:20:28   duration_ms: 0.949
03:20:28   severity: fail
03:20:28   exitcode: 1
03:20:28   stack: |-
03:20:28     events.js:167
03:20:28           throw er; // Unhandled 'error' event
03:20:28           ^
03:20:28     
03:20:28     Error: 281473541976064:error:140943FC:SSL routines:ssl3_read_bytes:sslv3 alert bad record mac:../deps/openssl/openssl/ssl/record/rec_layer_s3.c:1407:SSL alert number 20
03:20:28     
03:20:28         at DuplexSocket.ondata (internal/wrap_js_stream.js:64:22)
03:20:28         at DuplexSocket.emit (events.js:182:13)
03:20:28         at addChunk (_stream_readable.js:283:12)
03:20:28         at readableAddChunk (_stream_readable.js:264:11)
03:20:28         at DuplexSocket.Readable.push (_stream_readable.js:219:10)
03:20:28         at DuplexSocket._write (/home/iojs/build/workspace/node-test-commit-arm/nodes/ubuntu1604-arm64/test/common/duplexpair.js:28:22)
03:20:28         at doWrite (_stream_writable.js:410:12)
03:20:28         at clearBuffer (_stream_writable.js:540:7)
03:20:28         at DuplexSocket.Writable.uncork (_stream_writable.js:314:7)
03:20:28         at JSStreamWrap.doWrite (internal/wrap_js_stream.js:153:17)
03:20:28     Emitted 'error' event at:
03:20:28         at TLSSocket._emitTLSError (_tls_wrap.js:601:10)
03:20:28         at TLSWrap.onerror (_tls_wrap.js:267:11)
03:20:28         at DuplexSocket.ondata (internal/wrap_js_stream.js:64:22)
03:20:28         [... lines matching original stack trace ...]
03:20:28         at clearBuffer (_stream_writable.js:540:7)
03:20:28   ...

thefourtheye · 2018-10-04T09:25:18Z

test/internet/test-uv-threadpool-schedule.js

+'use strict';
+
+// test to validate massive dns lookups do not block filesytem I/O
+// (or any fast I/O).Prior to https://github.com/libuv/libuv/pull/1845


Nit: Space after the dot.

thanks @thefourtheye - done.

thefourtheye · 2018-10-04T09:26:37Z

test/internet/test-uv-threadpool-schedule.js

+  // We need to refresh the domain string everytime,
+  // otherwise the TCP stack that cache the previous lookup
+  // returns result from memory, breaking all our Math.
+  dns.lookup(`${randomDomain()}.com`, {}, common.mustCall(() => {


Nit: The callback function can be moved out and used with common.mustCall(..., slowIOmax).

I moved the callback body out of the loop. However, issue with attaching expected call count to the common.mustCall is: the loop executes 100 times, and each time when we invoke common.mustCall with slowIOmax, the total expectation becomes 10K. So I left it as is (default:1). Hope this is fine with you?

I was thinking about something like

const onResolve = common.mustCall(..., slowIOmax); ... dns.lookup(..., onResolve);

But your current change is intuitive. Let's go with that.

Trott · 2018-10-04T11:56:11Z

ARM rebuild: https://ci.nodejs.org/job/node-test-commit-arm/18956/

Trott · 2018-10-04T11:57:01Z

Full CI re-run post-fixup: https://ci.nodejs.org/job/node-test-pull-request/17627/

addaleax

LGTM, but we might need to be careful about landing this because the libuv patch may be at fault for a regression in our tests, see nodejs/reliability#18 (comment)

gireeshpunathil · 2018-10-05T05:49:01Z

thanks @addaleax for the info. sure, let me hold this until the libuv refix lands in node.

gireeshpunathil · 2018-10-05T05:52:11Z

@addaleax - also if you can describe a higher level statement on the flakes that the current libuv caused, I can see if that scenario can be added to this test. Unfortunately I wasn't able to follow root cause of the recent flakes (at the thread level)

addaleax · 2018-10-05T05:56:40Z

@gireeshpunathil So … as far as I can tell, the issue was that slow_io_work_running was increased with one mutex locked, and decreased with another mutex locked; that left it vulnerable to race conditions between workers, and so writes to the variable could get lost. That could make it seem like we have exhausted our # of available threads for slow I/O work, when in reality they were idle; that in turn prevented new DNS requests from being executed, and so the tests linked in libuv/libuv#2021 stalled and eventually timed out.

I think any test that would perform a lot of fast DNS requests (e.g. for localhost) in a row would be hit by that bug, at least on some platforms?

Trott · 2018-11-21T14:17:44Z

@addaleax @gireeshpunathil Can this move forward? Or is it blocked on libuv for now? Or something else?

gireeshpunathil · 2018-11-21T14:50:31Z

I believe the test makes meaningful assertions only in the presence of libuv/libuv@daf04e8 , that is slated to land in node through libuv v1.24.x

gireeshpunathil · 2018-12-06T04:48:21Z

Resume Build CI: https://ci.nodejs.org/job/node-test-commit/24015/

gireeshpunathil · 2018-12-07T12:42:52Z

not sure what to make out of the CI result. the graphical view says something failed, but going into the link I can't see any?

gireeshpunathil · 2018-12-08T02:08:53Z

to be sure, re-run CI: https://ci.nodejs.org/job/node-test-commit/24081/

gireeshpunathil · 2018-12-09T07:15:53Z

Failures in both Linux and AIX are the same, test-cli-syntax that is supposedly addressed through #24907

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

gireeshpunathil · 2018-12-10T05:43:36Z

after many runs of CI in expectation of a green sign giving up for now!

test-cli-syntax needs to be fixed / bailed out of the suite.

I will attempt to debug that first to see what is happening.

gireeshpunathil · 2018-12-28T11:00:26Z

all the known failures are either marked as flaky or resolved; so another round of CI - looks like I can't resume from the old build, it is expired:
https://ci.nodejs.org/job/node-test-pull-request/19854/

gireeshpunathil · 2018-12-28T13:10:09Z

a test is timing out in arm. Resume Build CI: https://ci.nodejs.org/job/node-test-commit/24705/

gireeshpunathil · 2018-12-29T12:31:07Z

with 2 separate runs on arm and windows

https://ci.nodejs.org/job/node-test-commit-arm-fanned/5471/
https://ci.nodejs.org/job/node-test-commit-windows-fanned/23644/

now the CI gets a full green.

Validate that massive dns lookups do not block filesytem I/O (or any fast I/O for that matter). Prior to libuv/libuv#1845 few back-to-back dns lookup were sufficient to engage libuv threadpool workers in a blocking manner, throttling other work items that need the pool. this test acts as a regression test for the same. Start slow and fast I/Os together, and make sure fast I/O can complete in at least in 1/100th of time for slow I/O. Refs: libuv/libuv#1845 Refs: nodejs#8436 PR-URL: nodejs#23099 Reviewed-By: Sakthipriyan Vairamani <thechargingvolcano@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net>

Validate that massive dns lookups do not block filesytem I/O (or any fast I/O for that matter). Prior to libuv/libuv#1845 few back-to-back dns lookup were sufficient to engage libuv threadpool workers in a blocking manner, throttling other work items that need the pool. this test acts as a regression test for the same. Start slow and fast I/Os together, and make sure fast I/O can complete in at least in 1/100th of time for slow I/O. Refs: libuv/libuv#1845 Refs: #8436 PR-URL: #23099 Reviewed-By: Sakthipriyan Vairamani <thechargingvolcano@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net>

Trott · 2019-01-01T16:40:20Z

I'll open a separate issue, but this test failed on node-daily-master (the only place where internet tests are run) last night. Considering it was only added two days, that's probably cause for concern?

https://ci.nodejs.org/job/node-test-commit-custom-suites/810/default/console

test-rackspace-ubuntu1604-x64-1

00:02:11 not ok 25 internet/test-uv-threadpool-schedule
00:02:11   ---
00:02:11   duration_ms: 0.613
00:02:11   severity: fail
00:02:11   exitcode: 1
00:02:11   stack: |-
00:02:11     assert.js:351
00:02:11         throw err;
00:02:11         ^
00:02:11     
00:02:11     AssertionError [ERR_ASSERTION]: fast I/O took longer to complete, actual: 17, expected: 3.63
00:02:11         at GetAddrInfoReqWrap.onResolve (/home/iojs/build/workspace/node-test-commit-custom-suites/default/test/internet/test-uv-threadpool-schedule.js:41:12)
00:02:11         at GetAddrInfoReqWrap.callback (/home/iojs/build/workspace/node-test-commit-custom-suites/default/test/common/index.js:376:15)
00:02:11         at GetAddrInfoReqWrap.onlookup [as oncomplete] (dns.js:57:17)
00:02:11   ...

thefourtheye · 2019-01-07T16:16:36Z

Interesting. Looks like fast IO is really not 100 times faster than slow IO in our infra.

@gireeshpunathil Would it be okay to change the test to ensure that the fast IO takes lesser time (not 1/100th but simply fastIOtime < slowIOtime) than slow IO? Basically it will ensure that DNS lookups do not impact fs operations.

gireeshpunathil · 2019-01-07T16:32:55Z

@thefourtheye - yes, and that is @Trott's #25358

Validate that massive dns lookups do not block filesytem I/O (or any fast I/O for that matter). Prior to libuv/libuv#1845 few back-to-back dns lookup were sufficient to engage libuv threadpool workers in a blocking manner, throttling other work items that need the pool. this test acts as a regression test for the same. Start slow and fast I/Os together, and make sure fast I/O can complete in at least in 1/100th of time for slow I/O. Refs: libuv/libuv#1845 Refs: nodejs#8436 PR-URL: nodejs#23099 Reviewed-By: Sakthipriyan Vairamani <thechargingvolcano@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net>

Validate that massive dns lookups do not block filesytem I/O (or any fast I/O for that matter). Prior to libuv/libuv#1845 few back-to-back dns lookup were sufficient to engage libuv threadpool workers in a blocking manner, throttling other work items that need the pool. this test acts as a regression test for the same. Start slow and fast I/Os together, and make sure fast I/O can complete in at least in 1/100th of time for slow I/O. Refs: libuv/libuv#1845 Refs: #8436 PR-URL: #23099 Reviewed-By: Sakthipriyan Vairamani <thechargingvolcano@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net>

nodejs-github-bot added the test Issues and PRs related to the tests. label Sep 26, 2018

gireeshpunathil requested review from addaleax and Trott September 26, 2018 06:54

gireeshpunathil added dns Issues and PRs related to the dns subsystem. libuv Issues and PRs related to the libuv dependency or the uv binding. labels Sep 26, 2018

thefourtheye reviewed Sep 26, 2018

View reviewed changes

gireeshpunathil force-pushed the uv-threadpool-schedule branch from 95fdbbe to cfb651e Compare September 27, 2018 04:37

gireeshpunathil force-pushed the uv-threadpool-schedule branch from b114e0a to e2541ee Compare September 27, 2018 04:54

richardlau reviewed Sep 27, 2018

View reviewed changes

thefourtheye approved these changes Oct 4, 2018

View reviewed changes

addaleax approved these changes Oct 4, 2018

View reviewed changes

gireeshpunathil changed the title ~~test: add uv threadpool congestion regression test~~ [do not land] test: add uv threadpool congestion regression test Oct 5, 2018

addaleax mentioned this pull request Oct 5, 2018

unix,win: fix threadpool race condition libuv/libuv#2021

Closed

Trott added the blocked PRs that are blocked by other issues or PRs. label Nov 21, 2018

gireeshpunathil force-pushed the uv-threadpool-schedule branch from 04786b3 to 05c3ae9 Compare December 28, 2018 11:28

gireeshpunathil added the author ready PRs that have at least one approval, no pending requests for changes, and a CI started. label Dec 29, 2018

gireeshpunathil force-pushed the uv-threadpool-schedule branch from 05c3ae9 to 54fa59c Compare December 30, 2018 14:18

gireeshpunathil merged commit 54fa59c into nodejs:master Dec 30, 2018

BridgeAR mentioned this pull request Jan 16, 2019

v11.7.0 proposal #25537

Merged

MylesBorins mentioned this pull request Jan 24, 2019

v11.8.0 proposal #25687

Merged

BethGriggs mentioned this pull request May 1, 2019

v10.16.0 proposal #27514

Merged

test: add uv threadpool congestion regression test #23099

test: add uv threadpool congestion regression test #23099

Conversation

gireeshpunathil commented Sep 26, 2018

Checklist

nodejs-github-bot commented Sep 26, 2018

Trott commented Sep 26, 2018

cjihrig commented Sep 26, 2018

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

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

gireeshpunathil commented Sep 27, 2018

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

gireeshpunathil commented Sep 28, 2018

Trott commented Sep 30, 2018

gireeshpunathil commented Sep 30, 2018

gireeshpunathil commented Oct 4, 2018

gireeshpunathil commented Oct 4, 2018

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

Trott commented Oct 4, 2018

Trott commented Oct 4, 2018

addaleax left a comment

Choose a reason for hiding this comment

gireeshpunathil commented Oct 5, 2018

gireeshpunathil commented Oct 5, 2018

addaleax commented Oct 5, 2018

Trott commented Nov 21, 2018

gireeshpunathil commented Nov 21, 2018

gireeshpunathil commented Dec 6, 2018

gireeshpunathil commented Dec 7, 2018

gireeshpunathil commented Dec 8, 2018

gireeshpunathil commented Dec 9, 2018

gireeshpunathil commented Dec 10, 2018

gireeshpunathil commented Dec 28, 2018

gireeshpunathil commented Dec 28, 2018

gireeshpunathil commented Dec 29, 2018

Trott commented Jan 1, 2019

thefourtheye commented Jan 7, 2019

gireeshpunathil commented Jan 7, 2019