Node: Investigate flaky parallel/test-worker-memory

Created on 5 Oct 2018  Ā·  27Comments  Ā·  Source: nodejs/node

https://ci.nodejs.org/job/node-test-commit-arm/18980/nodes=centos7-arm64-gcc6/console

00:03:00 not ok 2022 parallel/test-worker-memory
00:03:00   ---
00:03:00   duration_ms: 1.17
00:03:00   severity: crashed
00:03:00   exitcode: -7
00:03:00   stack: |-
00:03:00   ...
CI / flaky test windows worker
Source
picture Trott
👍1

Most helpful comment

Well ā€¦ https://github.com/nodejs/node/pull/25907 might be a candidate for fixing part of this on Windows, if itā€™s an ā€œsomethingā€™s keeping the event loop openā€ situation.

So Iā€™ll land this and kick off stress tests to compare:

It wonā€™t affect other platforms, though.

@Trott I think the AIX issue from the other thread would not hold for OSes like Windows or Linux, or explain why this test fails as the Workers themselves donā€™t do any actual CPU-heavy work.

picture addaleax on 5 Feb 2019
❤1 🎉1 👍1

All 27 comments

Different:

https://ci.nodejs.org/job/node-test-commit-linux/22212/nodes=ubuntu1804-docker/console

00:51:34 not ok 2141 parallel/test-worker-memory
00:51:34   ---
00:51:34   duration_ms: 120.40
00:51:34   severity: fail
00:51:34   exitcode: -15
00:51:34   stack: |-
00:51:34     timeout
Trott picture Trott on 10 Oct 2018

@nodejs/workers

Trott picture Trott on 10 Oct 2018

https://ci.nodejs.org/job/node-test-binary-windows/20610/COMPILED_BY=vs2017,RUNNER=win2008r2-vs2017,RUN_SUBSET=0/console

08:12:48 not ok 519 parallel/test-worker-memory
08:12:48   ---
08:12:48   duration_ms: 120.92
08:12:48   severity: fail
08:12:48   exitcode: 1
08:12:48   stack: |-
08:12:48     timeout
08:12:48   ...
Trott picture Trott on 11 Oct 2018

Itā€™s unfortunate that none of these have any console outputā€¦ -7 would be SIGBUS on arm Linux, if I am correct, which is something that could point to an actual bug.

addaleax picture addaleax on 11 Oct 2018

Itā€™s unfortunate that none of these have any console outputā€¦ -7 would be SIGBUS on arm Linux, if I am correct, which is something that could point to an actual bug.

We can add some console.log() calls to get an idea where the thing is getting hung up.

Trott picture Trott on 11 Oct 2018

Some minimal logging added in https://github.com/nodejs/node/pull/23418.

Trott picture Trott on 11 Oct 2018

Example failure with logging:

run() called with n=15 (numWorkers=4)
run() called with n=15 (numWorkers=4)
run() called with n=15 (numWorkers=4)
run() called with n=15 (numWorkers=4)
run() called with n=14 (numWorkers=4)
run() called with n=14 (numWorkers=4)
run() called with n=14 (numWorkers=4)
run() called with n=14 (numWorkers=4)
run() called with n=13 (numWorkers=4)
run() called with n=13 (numWorkers=4)
run() called with n=13 (numWorkers=4)
run() called with n=13 (numWorkers=4)
run() called with n=12 (numWorkers=4)
run() called with n=12 (numWorkers=4)
run() called with n=12 (numWorkers=4)
run() called with n=12 (numWorkers=4)
run() called with n=11 (numWorkers=4)
run() called with n=11 (numWorkers=4)
run() called with n=11 (numWorkers=4)
run() called with n=11 (numWorkers=4)
run() called with n=10 (numWorkers=4)
run() called with n=10 (numWorkers=4)
run() called with n=10 (numWorkers=4)
run() called with n=10 (numWorkers=4)
run() called with n=9 (numWorkers=4)
run() called with n=9 (numWorkers=4)
run() called with n=9 (numWorkers=4)
run() called with n=9 (numWorkers=4)
run() called with n=8 (numWorkers=4)
run() called with n=8 (numWorkers=4)
run() called with n=8 (numWorkers=4)
run() called with n=8 (numWorkers=4)
run() called with n=7 (numWorkers=4)
run() called with n=7 (numWorkers=4)
run() called with n=7 (numWorkers=4)
run() called with n=7 (numWorkers=4)

https://ci.nodejs.org/job/node-test-commit-linux-containered/nodes=ubuntu1604_sharedlibs_zlib_x64/7859/testReport/(root)/test/parallel_test_worker_memory/

targos picture targos on 16 Oct 2018
👍1

Is there more logging we should add? Is it just taking a while? n keeps decreasing. So maybe the test just needs to be moved to sequential and/or have its iterations (or something else) reduced?

Also happened in https://ci.nodejs.org/job/node-test-commit-linux-containered/7855/nodes=ubuntu1604_sharedlibs_zlib_x64/console:

00:40:04 not ok 2193 parallel/test-worker-memory
00:40:04   ---
00:40:04   duration_ms: 120.161
00:40:04   severity: fail
00:40:04   exitcode: -15
00:40:04   stack: |-
00:40:04     timeout
00:40:04     run() called with n=15 (numWorkers=4)
00:40:04     run() called with n=15 (numWorkers=4)
00:40:04     run() called with n=15 (numWorkers=4)
00:40:04     run() called with n=15 (numWorkers=4)
00:40:04     run() called with n=14 (numWorkers=4)
00:40:04     run() called with n=14 (numWorkers=4)
00:40:04     run() called with n=14 (numWorkers=4)
00:40:04     run() called with n=14 (numWorkers=4)
00:40:04     run() called with n=13 (numWorkers=4)
00:40:04     run() called with n=13 (numWorkers=4)
00:40:04     run() called with n=13 (numWorkers=4)
00:40:04     run() called with n=13 (numWorkers=4)
00:40:04     run() called with n=12 (numWorkers=4)
00:40:04     run() called with n=12 (numWorkers=4)
00:40:04     run() called with n=12 (numWorkers=4)
00:40:04     run() called with n=12 (numWorkers=4)
00:40:04     run() called with n=11 (numWorkers=4)
00:40:04     run() called with n=11 (numWorkers=4)
00:40:04     run() called with n=11 (numWorkers=4)
00:40:04     run() called with n=11 (numWorkers=4)
00:40:04     run() called with n=10 (numWorkers=4)
00:40:04     run() called with n=10 (numWorkers=4)
00:40:04     run() called with n=10 (numWorkers=4)
00:40:04     run() called with n=10 (numWorkers=4)
00:40:04     run() called with n=9 (numWorkers=4)
00:40:04     run() called with n=9 (numWorkers=4)
00:40:04     run() called with n=9 (numWorkers=4)
00:40:04     run() called with n=9 (numWorkers=4)
00:40:04     run() called with n=8 (numWorkers=4)
00:40:04     run() called with n=8 (numWorkers=4)
00:40:04     run() called with n=8 (numWorkers=4)
00:40:04     run() called with n=7 (numWorkers=4)
00:40:04     run() called with n=8 (numWorkers=4)
00:40:04     run() called with n=7 (numWorkers=4)
00:40:04     run() called with n=7 (numWorkers=4)
00:40:04     run() called with n=6 (numWorkers=4)
00:40:04     run() called with n=7 (numWorkers=4)
00:40:04     run() called with n=6 (numWorkers=4)
00:40:04     run() called with n=5 (numWorkers=4)
00:40:04     run() called with n=6 (numWorkers=4)
00:40:04     run() called with n=6 (numWorkers=4)
00:40:04   ...
Trott picture Trott on 16 Oct 2018

https://ci.nodejs.org/job/node-test-commit-arm/19636/nodes=ubuntu1604-arm64/console

19:53:45 not ok 2011 parallel/test-worker-memory
19:53:45   ---
19:53:45   duration_ms: 1.535
19:53:45   severity: crashed
19:53:45   exitcode: -11
19:53:45   stack: |-
19:53:45     run() called with n=1.2 (numWorkers=50)
19:53:45     run() called with n=1.2 (numWorkers=50)
19:53:45     run() called with n=1.2 (numWorkers=50)
19:53:45     run() called with n=1.2 (numWorkers=50)
19:53:45     run() called with n=1.2 (numWorkers=50)
19:53:45     run() called with n=1.2 (numWorkers=50)
19:53:45     run() called with n=1.2 (numWorkers=50)
19:53:45     run() called with n=1.2 (numWorkers=50)
19:53:45     run() called with n=1.2 (numWorkers=50)
19:53:45     run() called with n=1.2 (numWorkers=50)
19:53:45     run() called with n=1.2 (numWorkers=50)
19:53:45     run() called with n=1.2 (numWorkers=50)
19:53:45     run() called with n=1.2 (numWorkers=50)
19:53:45     run() called with n=1.2 (numWorkers=50)
19:53:45     run() called with n=1.2 (numWorkers=50)
19:53:45     run() called with n=1.2 (numWorkers=50)
19:53:45     run() called with n=1.2 (numWorkers=50)
19:53:45     run() called with n=1.2 (numWorkers=50)
19:53:45     run() called with n=1.2 (numWorkers=50)
19:53:45     run() called with n=1.2 (numWorkers=50)
19:53:45     run() called with n=1.2 (numWorkers=50)
19:53:45     run() called with n=1.2 (numWorkers=50)
19:53:45     run() called with n=1.2 (numWorkers=50)
19:53:45     run() called with n=1.2 (numWorkers=50)
19:53:45     run() called with n=1.2 (numWorkers=50)
19:53:45     run() called with n=1.2 (numWorkers=50)
19:53:45   ...
Trott picture Trott on 2 Nov 2018

I'm finding this test pretty easy to crash locally. Seems like perhaps a candidate to move to sequential (or find a way to have it run with fewer workers).

$ tools/test.py -j 32 --repeat 64 test/parallel/test-worker-memory.js 
=== release test-worker-memory ===                    
Path: parallel/test-worker-memory
run() called with n=15 (numWorkers=4)
run() called with n=15 (numWorkers=4)
run() called with n=15 (numWorkers=4)
run() called with n=15 (numWorkers=4)
run() called with n=14 (numWorkers=4)
run() called with n=14 (numWorkers=4)
run() called with n=14 (numWorkers=4)
run() called with n=14 (numWorkers=4)
run() called with n=13 (numWorkers=4)
run() called with n=13 (numWorkers=4)
run() called with n=13 (numWorkers=4)
run() called with n=13 (numWorkers=4)
run() called with n=12 (numWorkers=4)
run() called with n=12 (numWorkers=4)
run() called with n=12 (numWorkers=4)
run() called with n=12 (numWorkers=4)
run() called with n=11 (numWorkers=4)
run() called with n=11 (numWorkers=4)
run() called with n=11 (numWorkers=4)
run() called with n=11 (numWorkers=4)
run() called with n=10 (numWorkers=4)
run() called with n=10 (numWorkers=4)
run() called with n=10 (numWorkers=4)
run() called with n=10 (numWorkers=4)
run() called with n=9 (numWorkers=4)
run() called with n=9 (numWorkers=4)
run() called with n=9 (numWorkers=4)
run() called with n=9 (numWorkers=4)
run() called with n=8 (numWorkers=4)
run() called with n=8 (numWorkers=4)
run() called with n=8 (numWorkers=4)
run() called with n=8 (numWorkers=4)
run() called with n=7 (numWorkers=4)
run() called with n=7 (numWorkers=4)
run() called with n=7 (numWorkers=4)
run() called with n=7 (numWorkers=4)
run() called with n=6 (numWorkers=4)
run() called with n=6 (numWorkers=4)
run() called with n=6 (numWorkers=4)
run() called with n=6 (numWorkers=4)
run() called with n=5 (numWorkers=4)
run() called with n=5 (numWorkers=4)
run() called with n=5 (numWorkers=4)
run() called with n=5 (numWorkers=4)
run() called with n=4 (numWorkers=4)
run() called with n=4 (numWorkers=4)
run() called with n=4 (numWorkers=4)
out/Release/node[15392]: ../src/node_worker.cc:98:node::worker::Worker::Worker(node::Environment *, Local<v8::Object>, const std::string &): Assertion `(uv_loop_init(&loop_)) == (0)' failed.
 1: 0x10005edb3 node::Abort() [/Users/trott/io.js/out/Release/node]
 2: 0x10005ecf0 node::PrintErrorString(char const*, ...) [/Users/trott/io.js/out/Release/node]
 3: 0x1000c56fa node::worker::Worker::Worker(node::Environment*, v8::Local<v8::Object>, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&) [/Users/trott/io.js/out/Release/node]
 4: 0x1000c679d node::worker::Worker::New(v8::FunctionCallbackInfo<v8::Value> const&) [/Users/trott/io.js/out/Release/node]
 5: 0x10022efb4 v8::internal::FunctionCallbackArguments::Call(v8::internal::CallHandlerInfo*) [/Users/trott/io.js/out/Release/node]
 6: 0x10022e21b v8::internal::MaybeHandle<v8::internal::Object> v8::internal::(anonymous namespace)::HandleApiCallHelper<true>(v8::internal::Isolate*, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::FunctionTemplateInfo>, v8::internal::Handle<v8::internal::Object>, v8::internal::BuiltinArguments) [/Users/trott/io.js/out/Release/node]
 7: 0x10022dbf9 v8::internal::Builtin_Impl_HandleApiCall(v8::internal::BuiltinArguments, v8::internal::Isolate*) [/Users/trott/io.js/out/Release/node]
 8: 0x3b503064fb7d
Command: out/Release/node --experimental-worker /Users/trott/io.js/test/parallel/test-worker-memory.js
--- CRASHED (Signal: 6) ---
=== release test-worker-memory ===                    
Path: parallel/test-worker-memory
run() called with n=15 (numWorkers=4)
run() called with n=15 (numWorkers=4)
run() called with n=15 (numWorkers=4)
run() called with n=15 (numWorkers=4)
run() called with n=14 (numWorkers=4)
run() called with n=14 (numWorkers=4)
run() called with n=14 (numWorkers=4)
run() called with n=14 (numWorkers=4)
run() called with n=13 (numWorkers=4)
run() called with n=13 (numWorkers=4)
run() called with n=13 (numWorkers=4)
run() called with n=13 (numWorkers=4)
run() called with n=12 (numWorkers=4)
run() called with n=12 (numWorkers=4)
run() called with n=12 (numWorkers=4)
run() called with n=12 (numWorkers=4)
run() called with n=11 (numWorkers=4)
run() called with n=11 (numWorkers=4)
run() called with n=11 (numWorkers=4)
run() called with n=11 (numWorkers=4)
run() called with n=10 (numWorkers=4)
run() called with n=10 (numWorkers=4)
run() called with n=10 (numWorkers=4)
run() called with n=10 (numWorkers=4)
run() called with n=9 (numWorkers=4)
run() called with n=9 (numWorkers=4)
run() called with n=9 (numWorkers=4)
run() called with n=9 (numWorkers=4)
run() called with n=8 (numWorkers=4)
run() called with n=8 (numWorkers=4)
run() called with n=8 (numWorkers=4)
run() called with n=8 (numWorkers=4)
run() called with n=7 (numWorkers=4)
run() called with n=7 (numWorkers=4)
run() called with n=7 (numWorkers=4)
run() called with n=6 (numWorkers=4)
run() called with n=7 (numWorkers=4)
run() called with n=6 (numWorkers=4)
run() called with n=6 (numWorkers=4)
run() called with n=5 (numWorkers=4)
run() called with n=6 (numWorkers=4)
run() called with n=5 (numWorkers=4)
run() called with n=5 (numWorkers=4)
run() called with n=4 (numWorkers=4)
run() called with n=5 (numWorkers=4)
run() called with n=4 (numWorkers=4)
run() called with n=4 (numWorkers=4)
events.js:167
      throw er; // Unhandled 'error' event
      ^
Error: ENFILE: file table overflow, uv_cwd
    at MessagePort.port.on (internal/worker.js:453:50)
    at MessagePort.emit (events.js:182:13)
    at MessagePort.onmessage (internal/worker.js:84:8)
Emitted 'error' event at:
    at Worker.[kOnErrorMessage] (internal/worker.js:332:10)
    at Worker.[kOnMessage] (internal/worker.js:342:37)
    at MessagePort.Worker.(anonymous function).on (internal/worker.js:279:57)
    at MessagePort.emit (events.js:182:13)
    at MessagePort.onmessage (internal/worker.js:84:8)
Command: out/Release/node --experimental-worker /Users/trott/io.js/test/parallel/test-worker-memory.js
=== release test-worker-memory ===                    
Path: parallel/test-worker-memory
run() called with n=15 (numWorkers=4)
run() called with n=15 (numWorkers=4)
run() called with n=15 (numWorkers=4)
run() called with n=15 (numWorkers=4)
run() called with n=14 (numWorkers=4)
run() called with n=14 (numWorkers=4)
run() called with n=14 (numWorkers=4)
run() called with n=14 (numWorkers=4)
run() called with n=13 (numWorkers=4)
run() called with n=13 (numWorkers=4)
run() called with n=13 (numWorkers=4)
run() called with n=13 (numWorkers=4)
run() called with n=12 (numWorkers=4)
run() called with n=12 (numWorkers=4)
run() called with n=12 (numWorkers=4)
run() called with n=12 (numWorkers=4)
run() called with n=11 (numWorkers=4)
run() called with n=11 (numWorkers=4)
run() called with n=11 (numWorkers=4)
run() called with n=11 (numWorkers=4)
run() called with n=10 (numWorkers=4)
run() called with n=10 (numWorkers=4)
run() called with n=10 (numWorkers=4)
run() called with n=10 (numWorkers=4)
run() called with n=9 (numWorkers=4)
run() called with n=9 (numWorkers=4)
run() called with n=9 (numWorkers=4)
run() called with n=9 (numWorkers=4)
run() called with n=8 (numWorkers=4)
run() called with n=8 (numWorkers=4)
run() called with n=8 (numWorkers=4)
run() called with n=8 (numWorkers=4)
run() called with n=7 (numWorkers=4)
run() called with n=7 (numWorkers=4)
run() called with n=7 (numWorkers=4)
run() called with n=7 (numWorkers=4)
run() called with n=6 (numWorkers=4)
run() called with n=6 (numWorkers=4)
run() called with n=6 (numWorkers=4)
run() called with n=5 (numWorkers=4)
run() called with n=6 (numWorkers=4)
run() called with n=5 (numWorkers=4)
run() called with n=5 (numWorkers=4)
run() called with n=4 (numWorkers=4)
run() called with n=5 (numWorkers=4)
run() called with n=4 (numWorkers=4)
run() called with n=4 (numWorkers=4)
events.js:167
      throw er; // Unhandled 'error' event
      ^
Error: ENFILE: file table overflow, uv_cwd
    at MessagePort.port.on (internal/worker.js:453:50)
    at MessagePort.emit (events.js:182:13)
    at MessagePort.onmessage (internal/worker.js:84:8)
Emitted 'error' event at:
    at Worker.[kOnErrorMessage] (internal/worker.js:332:10)
    at Worker.[kOnMessage] (internal/worker.js:342:37)
    at MessagePort.Worker.(anonymous function).on (internal/worker.js:279:57)
    at MessagePort.emit (events.js:182:13)
    at MessagePort.onmessage (internal/worker.js:84:8)
Command: out/Release/node --experimental-worker /Users/trott/io.js/test/parallel/test-worker-memory.js
=== release test-worker-memory ===                    
Path: parallel/test-worker-memory
run() called with n=15 (numWorkers=4)
run() called with n=15 (numWorkers=4)
run() called with n=15 (numWorkers=4)
run() called with n=15 (numWorkers=4)
run() called with n=14 (numWorkers=4)
run() called with n=14 (numWorkers=4)
run() called with n=14 (numWorkers=4)
run() called with n=14 (numWorkers=4)
run() called with n=13 (numWorkers=4)
run() called with n=13 (numWorkers=4)
run() called with n=13 (numWorkers=4)
run() called with n=13 (numWorkers=4)
run() called with n=12 (numWorkers=4)
run() called with n=12 (numWorkers=4)
run() called with n=12 (numWorkers=4)
run() called with n=12 (numWorkers=4)
run() called with n=11 (numWorkers=4)
run() called with n=11 (numWorkers=4)
run() called with n=11 (numWorkers=4)
run() called with n=11 (numWorkers=4)
run() called with n=10 (numWorkers=4)
run() called with n=10 (numWorkers=4)
run() called with n=10 (numWorkers=4)
run() called with n=10 (numWorkers=4)
run() called with n=9 (numWorkers=4)
run() called with n=9 (numWorkers=4)
run() called with n=9 (numWorkers=4)
run() called with n=9 (numWorkers=4)
run() called with n=8 (numWorkers=4)
run() called with n=8 (numWorkers=4)
run() called with n=8 (numWorkers=4)
run() called with n=8 (numWorkers=4)
run() called with n=7 (numWorkers=4)
run() called with n=7 (numWorkers=4)
run() called with n=7 (numWorkers=4)
run() called with n=7 (numWorkers=4)
run() called with n=6 (numWorkers=4)
run() called with n=6 (numWorkers=4)
run() called with n=6 (numWorkers=4)
run() called with n=5 (numWorkers=4)
run() called with n=6 (numWorkers=4)
run() called with n=5 (numWorkers=4)
run() called with n=5 (numWorkers=4)
run() called with n=4 (numWorkers=4)
run() called with n=5 (numWorkers=4)
run() called with n=4 (numWorkers=4)
run() called with n=4 (numWorkers=4)
run() called with n=4 (numWorkers=4)
out/Release/node[15404]: ../src/node_worker.cc:98:node::worker::Worker::Worker(node::Environment *, Local<v8::Object>, const std::string &): Assertion `(uv_loop_init(&loop_)) == (0)' failed.
 1: 0x10005edb3 node::Abort() [/Users/trott/io.js/out/Release/node]
 2: 0x10005ecf0 node::PrintErrorString(char const*, ...) [/Users/trott/io.js/out/Release/node]
 3: 0x1000c56fa node::worker::Worker::Worker(node::Environment*, v8::Local<v8::Object>, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&) [/Users/trott/io.js/out/Release/node]
 4: 0x1000c679d node::worker::Worker::New(v8::FunctionCallbackInfo<v8::Value> const&) [/Users/trott/io.js/out/Release/node]
 5: 0x10022efb4 v8::internal::FunctionCallbackArguments::Call(v8::internal::CallHandlerInfo*) [/Users/trott/io.js/out/Release/node]
 6: 0x10022e21b v8::internal::MaybeHandle<v8::internal::Object> v8::internal::(anonymous namespace)::HandleApiCallHelper<true>(v8::internal::Isolate*, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::FunctionTemplateInfo>, v8::internal::Handle<v8::internal::Object>, v8::internal::BuiltinArguments) [/Users/trott/io.js/out/Release/node]
 7: 0x10022dbf9 v8::internal::Builtin_Impl_HandleApiCall(v8::internal::BuiltinArguments, v8::internal::Isolate*) [/Users/trott/io.js/out/Release/node]
 8: 0x1dda888cfb7d
Command: out/Release/node --experimental-worker /Users/trott/io.js/test/parallel/test-worker-memory.js
--- CRASHED (Signal: 6) ---
=== release test-worker-memory ===                    
Path: parallel/test-worker-memory
run() called with n=15 (numWorkers=4)
run() called with n=15 (numWorkers=4)
run() called with n=15 (numWorkers=4)
run() called with n=15 (numWorkers=4)
run() called with n=14 (numWorkers=4)
run() called with n=14 (numWorkers=4)
run() called with n=14 (numWorkers=4)
run() called with n=14 (numWorkers=4)
run() called with n=13 (numWorkers=4)
run() called with n=13 (numWorkers=4)
run() called with n=13 (numWorkers=4)
run() called with n=13 (numWorkers=4)
run() called with n=12 (numWorkers=4)
run() called with n=12 (numWorkers=4)
run() called with n=12 (numWorkers=4)
run() called with n=12 (numWorkers=4)
run() called with n=11 (numWorkers=4)
run() called with n=11 (numWorkers=4)
run() called with n=11 (numWorkers=4)
run() called with n=11 (numWorkers=4)
run() called with n=10 (numWorkers=4)
run() called with n=10 (numWorkers=4)
run() called with n=10 (numWorkers=4)
run() called with n=10 (numWorkers=4)
run() called with n=9 (numWorkers=4)
run() called with n=9 (numWorkers=4)
run() called with n=9 (numWorkers=4)
run() called with n=9 (numWorkers=4)
run() called with n=8 (numWorkers=4)
run() called with n=8 (numWorkers=4)
run() called with n=8 (numWorkers=4)
run() called with n=8 (numWorkers=4)
run() called with n=7 (numWorkers=4)
run() called with n=7 (numWorkers=4)
run() called with n=7 (numWorkers=4)
run() called with n=7 (numWorkers=4)
run() called with n=6 (numWorkers=4)
run() called with n=6 (numWorkers=4)
run() called with n=6 (numWorkers=4)
run() called with n=6 (numWorkers=4)
run() called with n=5 (numWorkers=4)
run() called with n=5 (numWorkers=4)
run() called with n=5 (numWorkers=4)
run() called with n=5 (numWorkers=4)
run() called with n=4 (numWorkers=4)
run() called with n=4 (numWorkers=4)
run() called with n=4 (numWorkers=4)
run() called with n=4 (numWorkers=4)
run() called with n=3 (numWorkers=4)
run() called with n=3 (numWorkers=4)
out/Release/node[15405]: ../src/node_worker.cc:98:node::worker::Worker::Worker(node::Environment *, Local<v8::Object>, const std::string &): Assertion `(uv_loop_init(&loop_)) == (0)' failed.
 1: 0x10005edb3 node::Abort() [/Users/trott/io.js/out/Release/node]
 2: 0x10005ecf0 node::PrintErrorString(char const*, ...) [/Users/trott/io.js/out/Release/node]
 3: 0x1000c56fa node::worker::Worker::Worker(node::Environment*, v8::Local<v8::Object>, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&) [/Users/trott/io.js/out/Release/node]
 4: 0x1000c679d node::worker::Worker::New(v8::FunctionCallbackInfo<v8::Value> const&) [/Users/trott/io.js/out/Release/node]
 5: 0x10022efb4 v8::internal::FunctionCallbackArguments::Call(v8::internal::CallHandlerInfo*) [/Users/trott/io.js/out/Release/node]
 6: 0x10022e21b v8::internal::MaybeHandle<v8::internal::Object> v8::internal::(anonymous namespace)::HandleApiCallHelper<true>(v8::internal::Isolate*, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::FunctionTemplateInfo>, v8::internal::Handle<v8::internal::Object>, v8::internal::BuiltinArguments) [/Users/trott/io.js/out/Release/node]
 7: 0x10022dbf9 v8::internal::Builtin_Impl_HandleApiCall(v8::internal::BuiltinArguments, v8::internal::Isolate*) [/Users/trott/io.js/out/Release/node]
 8: 0x354d7cecfb7d
Command: out/Release/node --experimental-worker /Users/trott/io.js/test/parallel/test-worker-memory.js
--- CRASHED (Signal: 6) ---
=== release test-worker-memory ===                    
Path: parallel/test-worker-memory
run() called with n=15 (numWorkers=4)
run() called with n=15 (numWorkers=4)
run() called with n=15 (numWorkers=4)
run() called with n=15 (numWorkers=4)
run() called with n=14 (numWorkers=4)
run() called with n=14 (numWorkers=4)
run() called with n=14 (numWorkers=4)
run() called with n=14 (numWorkers=4)
run() called with n=13 (numWorkers=4)
run() called with n=13 (numWorkers=4)
run() called with n=13 (numWorkers=4)
run() called with n=13 (numWorkers=4)
run() called with n=12 (numWorkers=4)
run() called with n=12 (numWorkers=4)
run() called with n=12 (numWorkers=4)
run() called with n=12 (numWorkers=4)
run() called with n=11 (numWorkers=4)
run() called with n=11 (numWorkers=4)
run() called with n=11 (numWorkers=4)
run() called with n=11 (numWorkers=4)
run() called with n=10 (numWorkers=4)
run() called with n=10 (numWorkers=4)
run() called with n=10 (numWorkers=4)
run() called with n=10 (numWorkers=4)
run() called with n=9 (numWorkers=4)
run() called with n=9 (numWorkers=4)
run() called with n=9 (numWorkers=4)
run() called with n=9 (numWorkers=4)
run() called with n=8 (numWorkers=4)
run() called with n=8 (numWorkers=4)
run() called with n=8 (numWorkers=4)
run() called with n=7 (numWorkers=4)
run() called with n=8 (numWorkers=4)
run() called with n=7 (numWorkers=4)
run() called with n=7 (numWorkers=4)
run() called with n=6 (numWorkers=4)
run() called with n=6 (numWorkers=4)
run() called with n=7 (numWorkers=4)
run() called with n=6 (numWorkers=4)
run() called with n=5 (numWorkers=4)
run() called with n=5 (numWorkers=4)
run() called with n=6 (numWorkers=4)
run() called with n=5 (numWorkers=4)
run() called with n=4 (numWorkers=4)
run() called with n=4 (numWorkers=4)
run() called with n=5 (numWorkers=4)
run() called with n=4 (numWorkers=4)
run() called with n=3 (numWorkers=4)
run() called with n=3 (numWorkers=4)
run() called with n=4 (numWorkers=4)
out/Release/node[15403]: ../src/node_worker.cc:98:node::worker::Worker::Worker(node::Environment *, Local<v8::Object>, const std::string &): Assertion `(uv_loop_init(&loop_)) == (0)' failed.
 1: 0x10005edb3 node::Abort() [/Users/trott/io.js/out/Release/node]
 2: 0x10005ecf0 node::PrintErrorString(char const*, ...) [/Users/trott/io.js/out/Release/node]
 3: 0x1000c56fa node::worker::Worker::Worker(node::Environment*, v8::Local<v8::Object>, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&) [/Users/trott/io.js/out/Release/node]
 4: 0x1000c679d node::worker::Worker::New(v8::FunctionCallbackInfo<v8::Value> const&) [/Users/trott/io.js/out/Release/node]
 5: 0x10022efb4 v8::internal::FunctionCallbackArguments::Call(v8::internal::CallHandlerInfo*) [/Users/trott/io.js/out/Release/node]
 6: 0x10022e21b v8::internal::MaybeHandle<v8::internal::Object> v8::internal::(anonymous namespace)::HandleApiCallHelper<true>(v8::internal::Isolate*, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::FunctionTemplateInfo>, v8::internal::Handle<v8::internal::Object>, v8::internal::BuiltinArguments) [/Users/trott/io.js/out/Release/node]
 7: 0x10022dbf9 v8::internal::Builtin_Impl_HandleApiCall(v8::internal::BuiltinArguments, v8::internal::Isolate*) [/Users/trott/io.js/out/Release/node]
 8: 0x9f67ba4fb7d
Command: out/Release/node --experimental-worker /Users/trott/io.js/test/parallel/test-worker-memory.js
--- CRASHED (Signal: 6) ---
=== release test-worker-memory ===                    
Path: parallel/test-worker-memory
run() called with n=15 (numWorkers=4)
run() called with n=15 (numWorkers=4)
run() called with n=15 (numWorkers=4)
run() called with n=15 (numWorkers=4)
run() called with n=14 (numWorkers=4)
run() called with n=14 (numWorkers=4)
run() called with n=14 (numWorkers=4)
run() called with n=14 (numWorkers=4)
run() called with n=13 (numWorkers=4)
run() called with n=13 (numWorkers=4)
run() called with n=13 (numWorkers=4)
run() called with n=13 (numWorkers=4)
run() called with n=12 (numWorkers=4)
run() called with n=12 (numWorkers=4)
run() called with n=12 (numWorkers=4)
run() called with n=12 (numWorkers=4)
run() called with n=11 (numWorkers=4)
run() called with n=11 (numWorkers=4)
run() called with n=11 (numWorkers=4)
run() called with n=11 (numWorkers=4)
run() called with n=10 (numWorkers=4)
run() called with n=10 (numWorkers=4)
run() called with n=10 (numWorkers=4)
run() called with n=10 (numWorkers=4)
run() called with n=9 (numWorkers=4)
run() called with n=9 (numWorkers=4)
run() called with n=9 (numWorkers=4)
run() called with n=9 (numWorkers=4)
run() called with n=8 (numWorkers=4)
run() called with n=8 (numWorkers=4)
run() called with n=8 (numWorkers=4)
run() called with n=8 (numWorkers=4)
run() called with n=7 (numWorkers=4)
run() called with n=7 (numWorkers=4)
run() called with n=7 (numWorkers=4)
run() called with n=7 (numWorkers=4)
run() called with n=6 (numWorkers=4)
run() called with n=6 (numWorkers=4)
run() called with n=6 (numWorkers=4)
run() called with n=6 (numWorkers=4)
run() called with n=5 (numWorkers=4)
run() called with n=5 (numWorkers=4)
run() called with n=5 (numWorkers=4)
run() called with n=5 (numWorkers=4)
run() called with n=4 (numWorkers=4)
run() called with n=4 (numWorkers=4)
run() called with n=4 (numWorkers=4)
run() called with n=4 (numWorkers=4)
run() called with n=3 (numWorkers=4)
run() called with n=3 (numWorkers=4)
run() called with n=3 (numWorkers=4)
run() called with n=3 (numWorkers=4)
run() called with n=2 (numWorkers=4)
run() called with n=2 (numWorkers=4)
run() called with n=2 (numWorkers=4)
run() called with n=2 (numWorkers=4)
run() called with n=1 (numWorkers=4)
out/Release/node[15410]: ../src/node_worker.cc:98:node::worker::Worker::Worker(node::Environment *, Local<v8::Object>, const std::string &): Assertion `(uv_loop_init(&loop_)) == (0)' failed.
 1: 0x10005edb3 node::Abort() [/Users/trott/io.js/out/Release/node]
 2: 0x10005ecf0 node::PrintErrorString(char const*, ...) [/Users/trott/io.js/out/Release/node]
 3: 0x1000c56fa node::worker::Worker::Worker(node::Environment*, v8::Local<v8::Object>, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&) [/Users/trott/io.js/out/Release/node]
 4: 0x1000c679d node::worker::Worker::New(v8::FunctionCallbackInfo<v8::Value> const&) [/Users/trott/io.js/out/Release/node]
 5: 0x10022efb4 v8::internal::FunctionCallbackArguments::Call(v8::internal::CallHandlerInfo*) [/Users/trott/io.js/out/Release/node]
 6: 0x10022e21b v8::internal::MaybeHandle<v8::internal::Object> v8::internal::(anonymous namespace)::HandleApiCallHelper<true>(v8::internal::Isolate*, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::FunctionTemplateInfo>, v8::internal::Handle<v8::internal::Object>, v8::internal::BuiltinArguments) [/Users/trott/io.js/out/Release/node]
 7: 0x10022dbf9 v8::internal::Builtin_Impl_HandleApiCall(v8::internal::BuiltinArguments, v8::internal::Isolate*) [/Users/trott/io.js/out/Release/node]
 8: 0x89d04d4fb7d
Command: out/Release/node --experimental-worker /Users/trott/io.js/test/parallel/test-worker-memory.js
--- CRASHED (Signal: 6) ---
[01:27|% 100|+  57|-   7]: Done
$

Trott picture Trott on 13 Nov 2018

Seems to now be showing up with some frequency on Windows, possibly only the win2008r2-vs2017 variant.

https://ci.nodejs.org/job/node-test-binary-windows/22438/COMPILED_BY=vs2017,RUNNER=win2008r2-vs2017,RUN_SUBSET=2/console

test-rackspace-win2008r2-x64-6

21:37:24 not ok 530 parallel/test-worker-memory
21:37:24   ---
21:37:24   duration_ms: 120.81
21:37:24   severity: fail
21:37:24   exitcode: 1
21:37:24   stack: |-
21:37:24     timeout
21:37:24     run() called with n=7.5 (numWorkers=8)
21:37:24     run() called with n=7.5 (numWorkers=8)
21:37:24     run() called with n=7.5 (numWorkers=8)
21:37:24     run() called with n=7.5 (numWorkers=8)
21:37:24     run() called with n=7.5 (numWorkers=8)
21:37:24     run() called with n=7.5 (numWorkers=8)
21:37:24     run() called with n=7.5 (numWorkers=8)
21:37:24     run() called with n=7.5 (numWorkers=8)
21:37:24     run() called with n=6.5 (numWorkers=8)
21:37:24     run() called with n=6.5 (numWorkers=8)
21:37:24     run() called with n=6.5 (numWorkers=8)
21:37:24     run() called with n=6.5 (numWorkers=8)
21:37:24     run() called with n=6.5 (numWorkers=8)
21:37:24     run() called with n=6.5 (numWorkers=8)
21:37:24     run() called with n=6.5 (numWorkers=8)
21:37:24     run() called with n=6.5 (numWorkers=8)
21:37:24     run() called with n=5.5 (numWorkers=8)
21:37:24     run() called with n=5.5 (numWorkers=8)
21:37:24     run() called with n=5.5 (numWorkers=8)
21:37:24     run() called with n=5.5 (numWorkers=8)
21:37:24     run() called with n=5.5 (numWorkers=8)
21:37:24     run() called with n=5.5 (numWorkers=8)
21:37:24     run() called with n=5.5 (numWorkers=8)
21:37:24     run() called with n=5.5 (numWorkers=8)
21:37:24     run() called with n=4.5 (numWorkers=8)
21:37:24     run() called with n=4.5 (numWorkers=8)
21:37:24     run() called with n=4.5 (numWorkers=8)
21:37:24     run() called with n=4.5 (numWorkers=8)
21:37:24     run() called with n=4.5 (numWorkers=8)
21:37:24     run() called with n=4.5 (numWorkers=8)
21:37:24     run() called with n=4.5 (numWorkers=8)
21:37:24     run() called with n=4.5 (numWorkers=8)
21:37:24     run() called with n=3.5 (numWorkers=8)
21:37:24     run() called with n=3.5 (numWorkers=8)
21:37:24     run() called with n=3.5 (numWorkers=8)
21:37:24     run() called with n=3.5 (numWorkers=8)
21:37:24     run() called with n=3.5 (numWorkers=8)
21:37:24     run() called with n=3.5 (numWorkers=8)
21:37:24     run() called with n=3.5 (numWorkers=8)
21:37:24     run() called with n=3.5 (numWorkers=8)
21:37:24     run() called with n=2.5 (numWorkers=8)
21:37:24     run() called with n=2.5 (numWorkers=8)
21:37:24     run() called with n=2.5 (numWorkers=8)
21:37:24     run() called with n=2.5 (numWorkers=8)
21:37:24     run() called with n=2.5 (numWorkers=8)
21:37:24     run() called with n=2.5 (numWorkers=8)
21:37:24     run() called with n=2.5 (numWorkers=8)
21:37:24     run() called with n=2.5 (numWorkers=8)
21:37:24     run() called with n=1.5 (numWorkers=8)
21:37:24     run() called with n=1.5 (numWorkers=8)
21:37:24     run() called with n=1.5 (numWorkers=8)
21:37:24     run() called with n=1.5 (numWorkers=8)
21:37:24     run() called with n=1.5 (numWorkers=8)
21:37:24     run() called with n=1.5 (numWorkers=8)
21:37:24     run() called with n=1.5 (numWorkers=8)
21:37:24     run() called with n=1.5 (numWorkers=8)
21:37:24     run() called with n=0.5 (numWorkers=8)
21:37:24     run() called with n=0.5 (numWorkers=8)
21:37:24     run() called with n=0.5 (numWorkers=8)
21:37:24     run() called with n=0.5 (numWorkers=8)
21:37:24     run() called with n=0.5 (numWorkers=8)
21:37:24     run() called with n=0.5 (numWorkers=8)
21:37:24     run() called with n=0.5 (numWorkers=8)
21:37:24     run() called with n=0.5 (numWorkers=8)
21:37:24     run() called with n=-0.5 (numWorkers=8)
21:37:24     done() called (finished=0)
21:37:24     run() called with n=-0.5 (numWorkers=8)
21:37:24     done() called (finished=1)
21:37:24     run() called with n=-0.5 (numWorkers=8)
21:37:24     done() called (finished=2)
21:37:24     run() called with n=-0.5 (numWorkers=8)
21:37:24     done() called (finished=3)
21:37:24     run() called with n=-0.5 (numWorkers=8)
21:37:24     done() called (finished=4)
21:37:24     run() called with n=-0.5 (numWorkers=8)
21:37:24     done() called (finished=5)
21:37:24     run() called with n=-0.5 (numWorkers=8)
21:37:24     done() called (finished=6)
21:37:24     run() called with n=-0.5 (numWorkers=8)
21:37:24     done() called (finished=7)
21:37:24   ...
Trott picture Trott on 14 Dec 2018

Appears to be specific to (or particularly prone to happen) on win2008r2-vs2017 in CI.

https://ci.nodejs.org/job/node-test-binary-windows/22443/COMPILED_BY=vs2017,RUNNER=win2008r2-vs2017,RUN_SUBSET=2/console

test-rackspace-win2008r2-x64-4

00:58:18 not ok 530 parallel/test-worker-memory
00:58:18   ---
00:58:18   duration_ms: 120.116
00:58:18   severity: fail
00:58:18   exitcode: 1
00:58:18   stack: |-
00:58:18     timeout
00:58:18     run() called with n=7.5 (numWorkers=8)
00:58:18     run() called with n=7.5 (numWorkers=8)
00:58:18     run() called with n=7.5 (numWorkers=8)
00:58:18     run() called with n=7.5 (numWorkers=8)
00:58:18     run() called with n=7.5 (numWorkers=8)
00:58:18     run() called with n=7.5 (numWorkers=8)
00:58:18     run() called with n=7.5 (numWorkers=8)
00:58:18     run() called with n=7.5 (numWorkers=8)
00:58:18     run() called with n=6.5 (numWorkers=8)
00:58:18     run() called with n=6.5 (numWorkers=8)
00:58:18     run() called with n=6.5 (numWorkers=8)
00:58:18     run() called with n=6.5 (numWorkers=8)
00:58:18     run() called with n=6.5 (numWorkers=8)
00:58:18     run() called with n=6.5 (numWorkers=8)
00:58:18     run() called with n=6.5 (numWorkers=8)
00:58:18     run() called with n=6.5 (numWorkers=8)
00:58:18     run() called with n=5.5 (numWorkers=8)
00:58:18     run() called with n=5.5 (numWorkers=8)
00:58:18     run() called with n=5.5 (numWorkers=8)
00:58:18     run() called with n=5.5 (numWorkers=8)
00:58:18     run() called with n=5.5 (numWorkers=8)
00:58:18     run() called with n=5.5 (numWorkers=8)
00:58:18     run() called with n=5.5 (numWorkers=8)
00:58:18     run() called with n=5.5 (numWorkers=8)
00:58:18     run() called with n=4.5 (numWorkers=8)
00:58:18     run() called with n=4.5 (numWorkers=8)
00:58:18     run() called with n=4.5 (numWorkers=8)
00:58:18     run() called with n=4.5 (numWorkers=8)
00:58:18     run() called with n=4.5 (numWorkers=8)
00:58:18     run() called with n=4.5 (numWorkers=8)
00:58:18     run() called with n=4.5 (numWorkers=8)
00:58:18     run() called with n=4.5 (numWorkers=8)
00:58:18     run() called with n=3.5 (numWorkers=8)
00:58:18     run() called with n=3.5 (numWorkers=8)
00:58:18     run() called with n=3.5 (numWorkers=8)
00:58:18     run() called with n=3.5 (numWorkers=8)
00:58:18     run() called with n=3.5 (numWorkers=8)
00:58:18     run() called with n=3.5 (numWorkers=8)
00:58:18     run() called with n=3.5 (numWorkers=8)
00:58:18     run() called with n=3.5 (numWorkers=8)
00:58:18     run() called with n=2.5 (numWorkers=8)
00:58:18     run() called with n=2.5 (numWorkers=8)
00:58:18     run() called with n=2.5 (numWorkers=8)
00:58:18     run() called with n=2.5 (numWorkers=8)
00:58:18     run() called with n=2.5 (numWorkers=8)
00:58:18     run() called with n=2.5 (numWorkers=8)
00:58:18     run() called with n=2.5 (numWorkers=8)
00:58:18     run() called with n=2.5 (numWorkers=8)
00:58:18     run() called with n=1.5 (numWorkers=8)
00:58:18     run() called with n=1.5 (numWorkers=8)
00:58:18     run() called with n=1.5 (numWorkers=8)
00:58:18     run() called with n=1.5 (numWorkers=8)
00:58:18     run() called with n=1.5 (numWorkers=8)
00:58:18     run() called with n=1.5 (numWorkers=8)
00:58:18     run() called with n=1.5 (numWorkers=8)
00:58:18     run() called with n=1.5 (numWorkers=8)
00:58:18     run() called with n=0.5 (numWorkers=8)
00:58:18     run() called with n=0.5 (numWorkers=8)
00:58:18     run() called with n=0.5 (numWorkers=8)
00:58:18     run() called with n=0.5 (numWorkers=8)
00:58:18     run() called with n=0.5 (numWorkers=8)
00:58:18     run() called with n=0.5 (numWorkers=8)
00:58:18     run() called with n=0.5 (numWorkers=8)
00:58:18     run() called with n=0.5 (numWorkers=8)
00:58:18     run() called with n=-0.5 (numWorkers=8)
00:58:18     done() called (finished=0)
00:58:18     run() called with n=-0.5 (numWorkers=8)
00:58:18     done() called (finished=1)
00:58:18     run() called with n=-0.5 (numWorkers=8)
00:58:18     done() called (finished=2)
00:58:18     run() called with n=-0.5 (numWorkers=8)
00:58:18     done() called (finished=3)
00:58:18     run() called with n=-0.5 (numWorkers=8)
00:58:18     done() called (finished=4)
00:58:18     run() called with n=-0.5 (numWorkers=8)
00:58:18     done() called (finished=5)
00:58:18     run() called with n=-0.5 (numWorkers=8)
00:58:18     done() called (finished=6)
00:58:18     run() called with n=-0.5 (numWorkers=8)
00:58:18     done() called (finished=7)
00:58:18   ...
Trott picture Trott on 14 Dec 2018

Output on Windows is now different (hopefully more informative but not entirely sure why it's different because I don't think the test has changed significantly). Continues to only show up on Rackspace Windows 2008r2 VS2017 hosts.

@nodejs/platform-windows @nodejs/build

https://ci.nodejs.org/job/node-test-binary-windows/23421/COMPILED_BY=vs2017,RUNNER=win2008r2-vs2017,RUN_SUBSET=2/console

test-rackspace-win2008r2-x64-4

00:56:48 not ok 535 parallel/test-worker-memory # TODO : Fix flaky test
00:56:48   ---
00:56:48   duration_ms: 1.417
00:56:48   severity: flaky
00:56:48   exitcode: 1
00:56:48   stack: |-
00:56:48     run() called with n=7.5 (numWorkers=8)
00:56:48     run() called with n=7.5 (numWorkers=8)
00:56:48     run() called with n=7.5 (numWorkers=8)
00:56:48     run() called with n=7.5 (numWorkers=8)
00:56:48     run() called with n=7.5 (numWorkers=8)
00:56:48     run() called with n=7.5 (numWorkers=8)
00:56:48     run() called with n=7.5 (numWorkers=8)
00:56:48     run() called with n=7.5 (numWorkers=8)
00:56:48     run() called with n=6.5 (numWorkers=8)
00:56:48     run() called with n=6.5 (numWorkers=8)
00:56:48     run() called with n=6.5 (numWorkers=8)
00:56:48     run() called with n=6.5 (numWorkers=8)
00:56:48     run() called with n=6.5 (numWorkers=8)
00:56:48     run() called with n=6.5 (numWorkers=8)
00:56:48     run() called with n=6.5 (numWorkers=8)
00:56:48     run() called with n=6.5 (numWorkers=8)
00:56:48     run() called with n=5.5 (numWorkers=8)
00:56:48     run() called with n=5.5 (numWorkers=8)
00:56:48     run() called with n=5.5 (numWorkers=8)
00:56:48     run() called with n=5.5 (numWorkers=8)
00:56:48     run() called with n=5.5 (numWorkers=8)
00:56:48     run() called with n=5.5 (numWorkers=8)
00:56:48     run() called with n=5.5 (numWorkers=8)
00:56:48     run() called with n=5.5 (numWorkers=8)
00:56:48     run() called with n=4.5 (numWorkers=8)
00:56:48     run() called with n=4.5 (numWorkers=8)
00:56:48     run() called with n=4.5 (numWorkers=8)
00:56:48     run() called with n=4.5 (numWorkers=8)
00:56:48     run() called with n=4.5 (numWorkers=8)
00:56:48     run() called with n=4.5 (numWorkers=8)
00:56:48     run() called with n=4.5 (numWorkers=8)
00:56:48     run() called with n=4.5 (numWorkers=8)
00:56:48     run() called with n=3.5 (numWorkers=8)
00:56:48     run() called with n=3.5 (numWorkers=8)
00:56:48     run() called with n=3.5 (numWorkers=8)
00:56:48     run() called with n=3.5 (numWorkers=8)
00:56:48     run() called with n=3.5 (numWorkers=8)
00:56:48     run() called with n=3.5 (numWorkers=8)
00:56:48     run() called with n=3.5 (numWorkers=8)
00:56:48     run() called with n=3.5 (numWorkers=8)
00:56:48     run() called with n=2.5 (numWorkers=8)
00:56:48     run() called with n=2.5 (numWorkers=8)
00:56:48     run() called with n=2.5 (numWorkers=8)
00:56:48     run() called with n=2.5 (numWorkers=8)
00:56:48     run() called with n=2.5 (numWorkers=8)
00:56:48     run() called with n=2.5 (numWorkers=8)
00:56:48     run() called with n=2.5 (numWorkers=8)
00:56:48     run() called with n=2.5 (numWorkers=8)
00:56:48     run() called with n=1.5 (numWorkers=8)
00:56:48     run() called with n=1.5 (numWorkers=8)
00:56:48     run() called with n=1.5 (numWorkers=8)
00:56:48     run() called with n=1.5 (numWorkers=8)
00:56:48     run() called with n=1.5 (numWorkers=8)
00:56:48     run() called with n=1.5 (numWorkers=8)
00:56:48     run() called with n=1.5 (numWorkers=8)
00:56:48     run() called with n=1.5 (numWorkers=8)
00:56:48     run() called with n=0.5 (numWorkers=8)
00:56:48     run() called with n=0.5 (numWorkers=8)
00:56:48     run() called with n=0.5 (numWorkers=8)
00:56:48     run() called with n=0.5 (numWorkers=8)
00:56:48     run() called with n=0.5 (numWorkers=8)
00:56:48     run() called with n=0.5 (numWorkers=8)
00:56:48     run() called with n=0.5 (numWorkers=8)
00:56:48     run() called with n=0.5 (numWorkers=8)
00:56:48     run() called with n=-0.5 (numWorkers=8)
00:56:48     done() called (finished=0)
00:56:48     run() called with n=-0.5 (numWorkers=8)
00:56:48     done() called (finished=1)
00:56:48     run() called with n=-0.5 (numWorkers=8)
00:56:48     done() called (finished=2)
00:56:48     run() called with n=-0.5 (numWorkers=8)
00:56:48     done() called (finished=3)
00:56:48     run() called with n=-0.5 (numWorkers=8)
00:56:48     done() called (finished=4)
00:56:48     run() called with n=-0.5 (numWorkers=8)
00:56:48     done() called (finished=5)
00:56:48     run() called with n=-0.5 (numWorkers=8)
00:56:48     done() called (finished=6)
00:56:48     Mismatched <anonymous> function calls. Expected exactly 1, actual 0.
00:56:48         at Object.mustCall (c:\workspace\node-test-binary-windows\test\common\index.js:334:10)
00:56:48         at run (c:\workspace\node-test-binary-windows\test\parallel\test-worker-memory.js:21:28)
00:56:48         at Worker.worker.on.common.mustCall (c:\workspace\node-test-binary-windows\test\parallel\test-worker-memory.js:22:5)
00:56:48         at Worker.<anonymous> (c:\workspace\node-test-binary-windows\test\common\index.js:368:15)
00:56:48         at Worker.emit (events.js:197:13)
00:56:48         at Worker.[kOnExit] (internal/worker.js:130:10)
00:56:48         at Worker.(anonymous function).onexit (internal/worker.js:82:51)
00:56:48     run() called with n=-0.5 (numWorkers=8)
00:56:48     done() called (finished=7)
00:56:48   ...
Trott picture Trott on 30 Jan 2019

https://ci.nodejs.org/job/node-test-binary-windows/23568/COMPILED_BY=vs2017-x86,RUNNER=win2012r2,RUN_SUBSET=0/console

test-rackspace-win2012r2-x64-4

00:59:26 not ok 537 parallel/test-worker-memory # TODO : Fix flaky test
00:59:26   ---
00:59:26   duration_ms: 120.74
00:59:26   severity: fail
00:59:26   exitcode: 1
00:59:26   stack: |-
00:59:26     timeout
00:59:26     run() called with n=7.5 (numWorkers=8)
00:59:26     run() called with n=7.5 (numWorkers=8)
00:59:26     run() called with n=7.5 (numWorkers=8)
00:59:26     run() called with n=7.5 (numWorkers=8)
00:59:26     run() called with n=7.5 (numWorkers=8)
00:59:26     run() called with n=7.5 (numWorkers=8)
00:59:26     run() called with n=7.5 (numWorkers=8)
00:59:26     run() called with n=7.5 (numWorkers=8)
00:59:26     run() called with n=6.5 (numWorkers=8)
00:59:26     run() called with n=6.5 (numWorkers=8)
00:59:26     run() called with n=6.5 (numWorkers=8)
00:59:26     run() called with n=6.5 (numWorkers=8)
00:59:26     run() called with n=6.5 (numWorkers=8)
00:59:26     run() called with n=6.5 (numWorkers=8)
00:59:26     run() called with n=6.5 (numWorkers=8)
00:59:26     run() called with n=6.5 (numWorkers=8)
00:59:26     run() called with n=5.5 (numWorkers=8)
00:59:26     run() called with n=5.5 (numWorkers=8)
00:59:26     run() called with n=5.5 (numWorkers=8)
00:59:26     run() called with n=5.5 (numWorkers=8)
00:59:26     run() called with n=5.5 (numWorkers=8)
00:59:26     run() called with n=5.5 (numWorkers=8)
00:59:26     run() called with n=5.5 (numWorkers=8)
00:59:26     run() called with n=5.5 (numWorkers=8)
00:59:26     run() called with n=4.5 (numWorkers=8)
00:59:26     run() called with n=4.5 (numWorkers=8)
00:59:26     run() called with n=4.5 (numWorkers=8)
00:59:26     run() called with n=4.5 (numWorkers=8)
00:59:26     run() called with n=4.5 (numWorkers=8)
00:59:26     run() called with n=4.5 (numWorkers=8)
00:59:26     run() called with n=4.5 (numWorkers=8)
00:59:26     run() called with n=4.5 (numWorkers=8)
00:59:26     run() called with n=3.5 (numWorkers=8)
00:59:26     run() called with n=3.5 (numWorkers=8)
00:59:26     run() called with n=3.5 (numWorkers=8)
00:59:26     run() called with n=3.5 (numWorkers=8)
00:59:26     run() called with n=3.5 (numWorkers=8)
00:59:26     run() called with n=3.5 (numWorkers=8)
00:59:26     run() called with n=3.5 (numWorkers=8)
00:59:26     run() called with n=2.5 (numWorkers=8)
00:59:26     run() called with n=3.5 (numWorkers=8)
00:59:26     run() called with n=2.5 (numWorkers=8)
00:59:26     run() called with n=2.5 (numWorkers=8)
00:59:26     run() called with n=2.5 (numWorkers=8)
00:59:26     run() called with n=2.5 (numWorkers=8)
00:59:26     run() called with n=2.5 (numWorkers=8)
00:59:26     run() called with n=2.5 (numWorkers=8)
00:59:26     run() called with n=1.5 (numWorkers=8)
00:59:26     run() called with n=2.5 (numWorkers=8)
00:59:26     run() called with n=1.5 (numWorkers=8)
00:59:26     run() called with n=1.5 (numWorkers=8)
00:59:26     run() called with n=1.5 (numWorkers=8)
00:59:26     run() called with n=1.5 (numWorkers=8)
00:59:26     run() called with n=1.5 (numWorkers=8)
00:59:26     run() called with n=1.5 (numWorkers=8)
00:59:26     run() called with n=0.5 (numWorkers=8)
00:59:26     run() called with n=1.5 (numWorkers=8)
00:59:26     run() called with n=0.5 (numWorkers=8)
00:59:26     run() called with n=0.5 (numWorkers=8)
00:59:26     run() called with n=0.5 (numWorkers=8)
00:59:26     run() called with n=0.5 (numWorkers=8)
00:59:26     run() called with n=0.5 (numWorkers=8)
00:59:26     run() called with n=0.5 (numWorkers=8)
00:59:26     run() called with n=-0.5 (numWorkers=8)
00:59:26     done() called (finished=0)
00:59:26     run() called with n=0.5 (numWorkers=8)
00:59:26     run() called with n=-0.5 (numWorkers=8)
00:59:26     done() called (finished=1)
00:59:26     run() called with n=-0.5 (numWorkers=8)
00:59:26     done() called (finished=2)
00:59:26     run() called with n=-0.5 (numWorkers=8)
00:59:26     done() called (finished=3)
00:59:26     run() called with n=-0.5 (numWorkers=8)
00:59:26     done() called (finished=4)
00:59:26     run() called with n=-0.5 (numWorkers=8)
00:59:26     done() called (finished=5)
00:59:26     run() called with n=-0.5 (numWorkers=8)
00:59:26     done() called (finished=6)
00:59:26     run() called with n=-0.5 (numWorkers=8)
00:59:26     done() called (finished=7)
00:59:26   ...
Trott picture Trott on 5 Feb 2019

In a typical successful run on test-rackspace-win2012r2-x64-* host, the test finishes in under 2 seconds.

04:36:20 ok 517 parallel/test-worker-memory
04:36:20   ---
04:36:20   duration_ms: 1.711
04:36:20   ...

And the output above in the error condition is the expected output for a successful run. So it seems that something somewhere is keeping the event loop open or otherwise preventing the process from exiting. Any ideas of something we could put in the test to help identify what is going on? Or maybe someone with the right version of Windows and sufficient debugging skills can take a dive into this?

@nodejs/libuv

Trott picture Trott on 5 Feb 2019

In https://github.com/nodejs/node/pull/25085#issuecomment-460671502, @gireeshpunathil wrote:

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.

@gireeshpunathil Could that explain what is happening in the test timing out we're seeing in https://github.com/nodejs/node/issues/23277#issuecomment-460666326? If so, would a setImmediate() in that test possibly solve the problem seen there? And if so, is that a legitimate solution or a workaround to a bug that needs fixing?

Trott picture Trott on 5 Feb 2019

Well ā€¦ https://github.com/nodejs/node/pull/25907 might be a candidate for fixing part of this on Windows, if itā€™s an ā€œsomethingā€™s keeping the event loop openā€ situation.

So Iā€™ll land this and kick off stress tests to compare:

It wonā€™t affect other platforms, though.

@Trott I think the AIX issue from the other thread would not hold for OSes like Windows or Linux, or explain why this test fails as the Workers themselves donā€™t do any actual CPU-heavy work.

addaleax picture addaleax on 5 Feb 2019
❤1 🎉1 👍1

Just for frugality I stopped 2149 early since it was positive:
'win2012r2-mp-vs2017': No. 79 OK: 60 NOT OK: 19 TOTAL: 1000

refack picture refack on 5 Feb 2019
👍1

The ā€œafterā€ stress test for win2012r2-mp-vs2017 came back green, and we canā€™t compare the results for win2016 because of the stopped run.

What now? Do we figure out if this is flaky on ARM and the sharedlibs_zlib_x64 ā€œcontaineredā€ build? I have no idea how to stress test for the latter.

addaleax picture addaleax on 5 Feb 2019

Stress test CI for the 2 ARM platforms on which this failed (+ linuxone as comparison): https://ci.nodejs.org/job/node-stress-single-test/2151/

addaleax picture addaleax on 5 Feb 2019

I have no idea how to stress test for the latter.

I'll run a stress test manually.

refack picture refack on 5 Feb 2019

Run on https://ci.nodejs.org/computer/test-digitalocean-ubuntu1604_sharedlibs_container-x64-2/

No repro ĀÆ\_(惄)_/ĀÆ

iojs@e8ed16a08d21:~/build/workspace/node-test-commit-linux-containered$ time python tools/test.py -J --repeat 5000 --mode=release parallel/test-worker-memory
[39:01|% 100|+ 5000|-   0]: Done

real    39m2.341s
user    201m22.408s
sys     26m30.328s
iojs@e8ed16a08d21:~/build/workspace/node-test-commit-linux-containered$ git log -1
commit 2ed556c11f1092e1207d3bba2dc01b29a61017a6
Author: cjihrig <[email protected]>
Date:   Sun Feb 3 12:07:35 2019 -0500

    report: print libuv handle addresses as hex

    PR-URL: https://github.com/nodejs/node/pull/25910
    Reviewed-By: Anna Henningsen <[email protected]>
    Reviewed-By: Ben Noordhuis <[email protected]>
    Reviewed-By: Richard Lau <[email protected]>
    Reviewed-By: James M Snell <[email protected]>
iojs@e8ed16a08d21:~/build/workspace/node-test-commit-linux-containered$
refack picture refack on 6 Feb 2019

Run on https://ci.nodejs.org/computer/test-digitalocean-ubuntu1604_sharedlibs_container-x64-2/

Only been seeing this on Windows lately (and older Windows at that). I don't think it's occurred on non-Windows since October.

Trott picture Trott on 6 Feb 2019

@Trott - on the question on can the linked AIX issue can explain this: I agree with @addaleax and no, the peculiarity which I described does not apply to Windows.

gireeshpunathil picture gireeshpunathil on 6 Feb 2019
👍1

Iā€™m going to close this, given the stress test results. Letā€™s reopen if it becomes problematic again in some way.

addaleax picture addaleax on 6 Feb 2019
🎉2

I am now tending to suspect that the behavior explained in https://github.com/nodejs/node/issues/21266#issuecomment-580655540 apply here. Therss memory to quiesce fully and come back to near-normal, there should be memory demand in other parts of the system, or else it just stays active in the current process.

gireeshpunathil picture gireeshpunathil on 1 Feb 2020

ok, I am able to confim my theory. I found a system where I can consistently reproduce this failure.

looking at the system spec w.r.t cpu and memory:

$ cat /proc/cpuinfo | grep processor | wc -l
120
$ cat /proc/meminfo | grep MemFree
MemFree:        1041442704 kB

in view of the rss theory, the issue now become evident - there was no drivers for pulling down the bloated rss.

diff --git a/test/parallel/test-worker-memory.js b/test/parallel/test-worker-memory.js
index 19b89d4..9d47271 100644
--- a/test/parallel/test-worker-memory.js
+++ b/test/parallel/test-worker-memory.js
@@ -38,7 +38,10 @@ for (let i = 0; i < numWorkers; ++i) {
   run(60 / numWorkers, () => {
     console.log(`done() called (finished=${finished})`);
     if (++finished === numWorkers) {
-      const finishStats = process.memoryUsage();
+      setInterval(() => {
+        const finishStats = process.memoryUsage();
+        console.log(Math.round(finishStats.rss / (1024 * 1024)))
+      }, 2000)
       // A typical value for this ratio would be ~1.15.
       // 5 as a upper limit is generous, but the main point is that we
       // don't have the memory of 50 Isolates/Node.js environments just lying

With this patch I kept the program alive, ran some load on the system, and saw the rss coming down.

I guess we need to devise a new stratgey for checking memory leak in this test case, without the usage of rss.

Re-opening this based on root cause identified.

gireeshpunathil picture gireeshpunathil on 3 Feb 2020
Was this page helpful?
0 / 5 - 0 ratings

Related issues

jonathanong picture jonathanong  Ā·  91Comments
jonathanong picture jonathanong  Ā·  93Comments
benjamingr picture benjamingr  Ā·  135Comments
ctavan picture ctavan  Ā·  87Comments
mikeal picture mikeal  Ā·  90Comments