test: exit sequence sanity tests [2] #25085

gireeshpunathil · 2018-12-17T09:52:08Z

Execute JS code in worker through same vm context
while exiting from the main thread at arbitrary
execution points, and make sure that the workers
quiesce without crashing.

worker_threads are not necessarily the subject of
testing, those are used for easy simulation of
multi-thread scenarios.

Refs: #25007

Checklist

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

nodejs-github-bot · 2018-12-17T09:52:10Z

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

gireeshpunathil · 2018-12-17T10:10:16Z

It captured a new error - good from test's perspective, but makes it a do-not-land-yet candidate

04:56:20 not ok 2057 parallel/test-worker-cleanexit-with-js
04:56:20   ---
04:56:20   duration_ms: 0.366
04:56:20   severity: fail
04:56:20   exitcode: 1
04:56:20   stack: |-
04:56:20     assert.js:86
04:56:20       throw new AssertionError(obj);
04:56:20       ^
04:56:20     
04:56:20     AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:
04:56:20     + actual - expected
04:56:20     
04:56:20     + "undefined/data/iojs/build/workspace/node-test-commit-linuxone/nodes/rhel72-s390x/out/Release/node[45062]: ../src/node_native_module.cc:102:v8::Local<v8::String> node::native_module::NativeModuleLoader::GetSource(v8::Isolate*, const char*) const: Assertion `(it) != (source_.end())' failed.\n"
04:56:20     - undefined
04:56:20         at ChildProcess.child.on.common.mustCall (/data/iojs/build/workspace/node-test-commit-linuxone/nodes/rhel72-s390x/test/parallel/test-worker-cleanexit-with-js.js:44:12)
04:56:20         at ChildProcess.<anonymous> (/data/iojs/build/workspace/node-test-commit-linuxone/nodes/rhel72-s390x/test/common/index.js:335:15)
04:56:20         at ChildProcess.emit (events.js:189:13)
04:56:20         at Process.ChildProcess._handle.onexit (internal/child_process.js:254:12)
04:56:20   ...

source line:

node/src/node_native_module.cc

Line 102 in a361b94

CHECK_NE(it, source_.end());

native stack:

(dbx) where
pthread_kill(??, ??) at 0x90000000051beb4
_p_raise(??) at 0x90000000051b6e8
raise.raise(??) at 0x90000000002bd4c
abort() at 0x9000000000827c4
_ZN4node5AbortEv() at 0x1001f2314
_ZN4node6AssertEPA4_KPKc(??) at 0x1001f23d0
_ZNK4node13native_module18NativeModuleLoader9GetSourceEPN2v87IsolateEPKc(??, ??, ??) at 0x100875330
_ZN4node13native_module18NativeModuleLoader16LookupAndCompileEN2v85LocalINS2_7ContextEEEPKcPSt6vectorINS3_INS2_6StringEEESaISA_EENS1_21CompilationResultTypeEPNS_11EnvironmentE(??, ??, ??, ??, ??, ??) at 0x100875e98
_ZN4node13native_module18NativeModuleLoader15CompileAsModuleEPNS_11EnvironmentEPKcNS1_21CompilationResultTypeE(??, ??, ??) at 0x1008768f4
_ZN4node13native_module18NativeModuleLoader15CompileFunctionERKN2v820FunctionCallbackInfoINS2_5ValueEEE(??) at 0x100876c28
builtins-api._ZN2v88internal12_GLOBAL__N_119HandleApiCallHelperILb0EEENS0_11MaybeHandleINS0_6ObjectEEEPNS0_7IsolateENS0_6HandleINS0_10HeapObjectEEESA_NS8_INS0_20FunctionTemplateInfoEEENS8_IS4_EENS0_16BuiltinArgumentsE(??, ??, ??, ??, ??, ??, ??) at 0x100048bf0

gireeshpunathil · 2019-01-29T13:48:27Z

this can easily be accommodated in #25083, but needs to stay separate as:

While it shares a common objective and structure, the operating space for the workers in this test is more of JS than C++, and have proven to capture new errors in relation to thread interactions.
these tests are sensitive to time, keeping separately makes sure no interference
debugging is easy if kept separately.

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

Trott · 2019-01-29T22:17:18Z

test/parallel/test-worker-cleanexit-with-js.js

+
+// Allow workers to go live.
+setTimeout(() => {
+  // process.exit(0);


Maybe remove the commented out line?

@Trott - it was a mistake to comment that out! The abrupt exit is required for the thread interactions to come in to play. I opened it up now.

so no wonder why CI did not report a single related failure. Realistically I was expecting one or two that this test can throw, based on its original run that threw up a lot!

gireeshpunathil · 2019-01-30T04:08:01Z

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

gireeshpunathil · 2019-01-30T13:19:08Z

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

test/parallel/test-worker-cleanexit-with-js.js

gireeshpunathil · 2019-02-05T12:23:00Z

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

gireeshpunathil · 2019-02-05T14:28:02Z

The test fails in AIX and Windows.
As it is evident, the test do not carry any issue - both are native crashes.
So I added a blocked label as opposed to WIP one.

AIX

18:08:15 not ok 2397 parallel/test-worker-cleanexit-with-js
18:08:15   ---
18:08:15   duration_ms: 120.217
18:08:15   severity: fail
18:08:15   exitcode: -15
18:08:15   stack: |-
18:08:15     timeout
18:08:15   ...

windows

18:52:34 not ok 534 parallel/test-worker-cleanexit-with-js
18:52:34   ---
18:52:34   duration_ms: 37.447
18:52:34   severity: fail
18:52:34   exitcode: -529697949
18:52:34   stack: |-

gireeshpunathil · 2019-02-05T14:29:37Z

sorry, it was timeout on AIX!

gireeshpunathil · 2019-02-05T15:06:41Z

Interesting story from AIX: In a system where the no. of CPUs are less than 10 (the number of workers in this test), the already spawned workers spin their full allotted time in the JS loop to cause OOM, before main thread gets into action - mostly it was de-scheduled while one or more workers ran.

So I want to revisit the while(true) loop - replace it with a setInterval . But before that will need to see what happens in Windows.

addaleax · 2019-02-05T17:09:31Z

@gireeshpunathil Is that normal for AIX/by design, non-preemptive multithreading?

gireeshpunathil · 2019-02-06T06:20:26Z

@addaleax - in terms of multi-tasking, there is nothing abnormal; AIX has a truly preemptive kernel.

The difference comes in way of deciding / allocating the current CPU post-fork: whether to continue to give it to the parent, or give child a chance and push parent to the next available cpu - only in the current slice of schedule cycle of the current thread of the current process. Since then all processes contend for CPU in a similar manner of Linux, driven by scheduler policies.

While no documented evidence exists, all my experiments has proven that:

Linux always runs the parent in the current CPU, consistently.
AIX 'mostly' gives it to the child. Reverse is also seen rarely, probably depends on factors internal to the scheduler.

cat tc.c

#include <unistd.h>
#include <stdio.h>
int main() {
  pid_t pid = fork();
  if (pid == 0) write(1, "child\n", 6);
  else write(1, "parent\n", 7);
}

linux:
parent
child

clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f824a355a10) = 100129
strace: Process 100129 attached
[pid 100128] write(1, "parent\n", 7)    = 7
[pid 100129] write(1, "child\n", 6)     = 6

aix:
child
parent

15270132: 100728997: kfork()                            = 18153586
18153586:       kfork()         (returning as child ...)        = 0
18153586:       23462101: kwrite(1, " c h i l d\n", 6)          = 6
18153586:       23462101: kfcntl(1, F_GETFL, 0x20000E0C)        = 67110914
18153586:       23462101: kfcntl(2, F_GETFL, 0x2FF22FFC)        = 67108865
18153586:       23462101: _exit(0)
15270132: 100728997: kwrite(1, " p a r e n t\n", 7)     = 7

the same applies to pthread_create as well.

In applications of most other languages this does not imply anything: slight difference in terms of CPU allocation, and who gets ahead slightly. But given that node threads can run millions of instructions without any blocking calls coming in between, this can cause visible differences in our workloads - such as many timing related issues we usually see in child process related tests.

So in this case one or more workers ate up their remaining slice leading upto OOM before main thread gets a CPU.

So I would like to revert the while loop with setInterval if you are good with that.

addaleax · 2019-02-06T10:07:10Z

@gireeshpunathil Sure, if you think so. It just seemed pretty odd to me that AIX would act like this/that this could would OOM.

gireeshpunathil · 2019-02-06T14:49:43Z

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

Execute JS code in worker through same vm context while exiting from the main thread at arbitrary execution points, and make sure that the workers quiesce without crashing. `worker_threads` are not necessarily the subject of testing, those are used for easy simulation of multi-thread scenarios. Refs: nodejs#25007 PR-URL: nodejs#25085 Reviewed-By: Anna Henningsen <anna@addaleax.net>

gireeshpunathil · 2019-02-08T04:48:22Z

landed as 2ea2000

Execute JS code in worker through same vm context while exiting from the main thread at arbitrary execution points, and make sure that the workers quiesce without crashing. `worker_threads` are not necessarily the subject of testing, those are used for easy simulation of multi-thread scenarios. Refs: #25007 PR-URL: #25085 Reviewed-By: Anna Henningsen <anna@addaleax.net>

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

gireeshpunathil added the wip Issues and PRs that are still a work in progress. label Dec 17, 2018

gireeshpunathil mentioned this pull request Dec 22, 2018

exit race between main and worker threads #25007

Closed

gireeshpunathil force-pushed the exitrace2 branch from 437f0d7 to aa0d7fa Compare January 29, 2019 13:42

gireeshpunathil removed the wip Issues and PRs that are still a work in progress. label Jan 29, 2019

gireeshpunathil requested review from addaleax and Trott January 29, 2019 15:33

Trott reviewed Jan 29, 2019

View reviewed changes

addaleax approved these changes Jan 30, 2019

View reviewed changes

test/parallel/test-worker-cleanexit-with-js.js Outdated Show resolved Hide resolved

test/parallel/test-worker-cleanexit-with-js.js Outdated Show resolved Hide resolved

gireeshpunathil force-pushed the exitrace2 branch 2 times, most recently from c17f254 to 4097ada Compare January 31, 2019 12:53

gireeshpunathil added the blocked PRs that are blocked by other issues or PRs. label Feb 5, 2019

Trott mentioned this pull request Feb 5, 2019

Investigate flaky parallel/test-worker-memory #23277

Closed

gireeshpunathil force-pushed the exitrace2 branch from 29c7138 to 2ea2000 Compare February 8, 2019 04:47

gireeshpunathil merged commit 2ea2000 into nodejs:master Feb 8, 2019

gireeshpunathil removed the blocked PRs that are blocked by other issues or PRs. label Feb 8, 2019

targos mentioned this pull request Feb 14, 2019

v11.10.0 proposal #26098

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

test: exit sequence sanity tests [2] #25085

test: exit sequence sanity tests [2] #25085

gireeshpunathil commented Dec 17, 2018

nodejs-github-bot commented Dec 17, 2018

gireeshpunathil commented Dec 17, 2018

gireeshpunathil commented Jan 29, 2019

Trott Jan 29, 2019

gireeshpunathil Jan 30, 2019

gireeshpunathil Jan 30, 2019

gireeshpunathil commented Jan 30, 2019

gireeshpunathil commented Jan 30, 2019

gireeshpunathil commented Feb 5, 2019

gireeshpunathil commented Feb 5, 2019

gireeshpunathil commented Feb 5, 2019

gireeshpunathil commented Feb 5, 2019

addaleax commented Feb 5, 2019

gireeshpunathil commented Feb 6, 2019

addaleax commented Feb 6, 2019

gireeshpunathil commented Feb 6, 2019

gireeshpunathil commented Feb 8, 2019

test: exit sequence sanity tests [2] #25085

test: exit sequence sanity tests [2] #25085

Conversation

gireeshpunathil commented Dec 17, 2018

Checklist

nodejs-github-bot commented Dec 17, 2018

gireeshpunathil commented Dec 17, 2018

gireeshpunathil commented Jan 29, 2019

Trott Jan 29, 2019

Choose a reason for hiding this comment

gireeshpunathil Jan 30, 2019

Choose a reason for hiding this comment

gireeshpunathil Jan 30, 2019

Choose a reason for hiding this comment

gireeshpunathil commented Jan 30, 2019

gireeshpunathil commented Jan 30, 2019

gireeshpunathil commented Feb 5, 2019

gireeshpunathil commented Feb 5, 2019

gireeshpunathil commented Feb 5, 2019

gireeshpunathil commented Feb 5, 2019

addaleax commented Feb 5, 2019

gireeshpunathil commented Feb 6, 2019

addaleax commented Feb 6, 2019

gireeshpunathil commented Feb 6, 2019

gireeshpunathil commented Feb 8, 2019