Allocation failed - JavaScript heap out of memory on v6.3.1

[dszakallas]

• Version: v6.3.1
• Platform: Linux railsonfire_cbc96846-1473-404d-a2be-333523784c6d_a72a70ef6cf2 4.2.0-42-generic debugger: use requireRepl() to load debugger repl #49~14.04.1-Ubuntu SMP Wed Jun 29 20:22:11 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux
• Subsystem: V8 Garbage Collection ?

On v6.3.1 we face an out of memory error, when running some unit tests regarding this module.

<--- Last few GCs --->

388968 ms: Mark-sweep 1273.2 (1434.6) -> 1273.1 (1434.6) MB, 546.0 / 0 ms [allocation failure] [GC in old space requested].
389494 ms: Mark-sweep 1273.1 (1434.6) -> 1273.1 (1434.6) MB, 526.1 / 0 ms [allocation failure] [GC in old space requested].
390010 ms: Mark-sweep 1273.1 (1434.6) -> 1273.1 (1434.6) MB, 515.9 / 0 ms [last resort gc].
390516 ms: Mark-sweep 1273.1 (1434.6) -> 1273.1 (1434.6) MB, 506.4 / 0 ms [last resort gc].


<--- JS stacktrace --->

==== JS stack trace =========================================

Security context: 0x172194ec9e31 <JS Object>
1: getMemory [/home/rof/src/github.com/RisingStack/trace-nodejs/lib/agent/metrics/apm/index.js:~67] [pc=0x2816fd631730] (this=0x3369498fa381 <an ApmMetrics with map 0x2477f6fbed39>)
2: sendMetrics [/home/rof/src/github.com/RisingStack/trace-nodejs/lib/agent/metrics/apm/index.js:50] [pc=0x2816fda2a3bf] (this=0x3369498fa381 <an ApmMetrics with map 0x2477f6fbed39>)
3: _repeat [/home/ro...

FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - JavaScript heap out of memory
1: node::Abort() [/home/rof/.nvm/versions/node/v6.3.1/bin/node]
2: 0xfb1c8c [/home/rof/.nvm/versions/node/v6.3.1/bin/node]
3: v8::Utils::ReportApiFailure(char const*, char const*) [/home/rof/.nvm/versions/node/v6.3.1/bin/node]
4: v8::internal::V8::FatalProcessOutOfMemory(char const*, bool) [/home/rof/.nvm/versions/node/v6.3.1/bin/node]
5: v8::internal::Factory::NewTransitionArray(int) [/home/rof/.nvm/versions/node/v6.3.1/bin/node]
6: v8::internal::TransitionArray::Allocate(v8::internal::Isolate*, int, int) [/home/rof/.nvm/versions/node/v6.3.1/bin/node]
7: v8::internal::TransitionArray::Insert(v8::internal::Handle<v8::internal::Map>, v8::internal::Handle<v8::internal::Name>, v8::internal::Handle<v8::internal::Map>, v8::internal::SimpleTransitionFlag) [/home/rof/.nvm/versions/node/v6.3.1/bin/node]
8: v8::internal::Map::CopyReplaceDescriptors(v8::internal::Handle<v8::internal::Map>, v8::internal::Handle<v8::internal::DescriptorArray>, v8::internal::Handle<v8::internal::LayoutDescriptor>, v8::internal::TransitionFlag, v8::internal::MaybeHandle<v8::internal::Name>, char const*, v8::internal::SimpleTransitionFlag) [/home/rof/.nvm/versions/node/v6.3.1/bin/node]
9: v8::internal::Map::CopyAddDescriptor(v8::internal::Handle<v8::internal::Map>, v8::internal::Descriptor*, v8::internal::TransitionFlag) [/home/rof/.nvm/versions/node/v6.3.1/bin/node]
10: v8::internal::Map::CopyWithField(v8::internal::Handle<v8::internal::Map>, v8::internal::Handle<v8::internal::Name>, v8::internal::Handle<v8::internal::FieldType>, v8::internal::PropertyAttributes, v8::internal::Representation, v8::internal::TransitionFlag) [/home/rof/.nvm/versions/node/v6.3.1/bin/node]
11: v8::internal::Map::TransitionToDataProperty(v8::internal::Handle<v8::internal::Map>, v8::internal::Handle<v8::internal::Name>, v8::internal::Handle<v8::internal::Object>, v8::internal::PropertyAttributes, v8::internal::Object::StoreFromKeyed) [/home/rof/.nvm/versions/node/v6.3.1/bin/node]
12: v8::internal::LookupIterator::PrepareTransitionToDataProperty(v8::internal::Handle<v8::internal::JSObject>, v8::internal::Handle<v8::internal::Object>, v8::internal::PropertyAttributes, v8::internal::Object::StoreFromKeyed) [/home/rof/.nvm/versions/node/v6.3.1/bin/node]
13: v8::internal::Object::AddDataProperty(v8::internal::LookupIterator*, v8::internal::Handle<v8::internal::Object>, v8::internal::PropertyAttributes, v8::internal::Object::ShouldThrow, v8::internal::Object::StoreFromKeyed) [/home/rof/.nvm/versions/node/v6.3.1/bin/node]
14: v8::internal::Object::SetProperty(v8::internal::LookupIterator*, v8::internal::Handle<v8::internal::Object>, v8::internal::LanguageMode, v8::internal::Object::StoreFromKeyed) [/home/rof/.nvm/versions/node/v6.3.1/bin/node]
15: v8::internal::Runtime::SetObjectProperty(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, v8::internal::LanguageMode) [/home/rof/.nvm/versions/node/v6.3.1/bin/node]
16: v8::Object::Set(v8::Local<v8::Context>, v8::Local<v8::Value>, v8::Local<v8::Value>) [/home/rof/.nvm/versions/node/v6.3.1/bin/node]
17: v8::Object::Set(v8::Local<v8::Value>, v8::Local<v8::Value>) [/home/rof/.nvm/versions/node/v6.3.1/bin/node]
18: node::MemoryUsage(v8::FunctionCallbackInfo<v8::Value> const&) [/home/rof/.nvm/versions/node/v6.3.1/bin/node]
19: v8::internal::FunctionCallbackArguments::Call(void (*)(v8::FunctionCallbackInfo<v8::Value> const&)) [/home/rof/.nvm/versions/node/v6.3.1/bin/node]
20: 0x9d5b0b [/home/rof/.nvm/versions/node/v6.3.1/bin/node]
21: 0x9d60b1 [/home/rof/.nvm/versions/node/v6.3.1/bin/node]
22: 0x2816fd50961b
Aborted (core dumped)

Steps to reproduce error:

git clone https://github.com/RisingStack/trace-nodejs.git
cd trace-nodejs
npm i 
npm run test-unit

v6.3.0 and v.6.2.2 are working fine, as well as earlier major versions (v5, v4, v0.12. v0.10).

[bnoordhuis]

Can you try running git bisect on the commits between v6.3.0 and v6.3.1? There are several changes that are potential suspects but I wouldn't want to guess.

Does it work with e.g. --max_old_space_size=3072?

[dszakallas]

I finished with bisecting and the culprit seems to be timers: fix processing of nested timers.

[bnoordhuis]

Thanks. Does upping --max_old_space_size make a difference?

[dszakallas]

It doesn't. I managed to find the source of the problem I think:
The introduced a change results in timers running on schedule. This change multiplied the number of due callbacks to be called / event loop iteration in our tests.
Moreover the timers with interval 0 were registered multiple times (in every test case) and never deregistered.
This overwhelmed the node process, that's why it run with ~100 CPU and finally crashed with OOM. I fixed this by changing our code.
If this issue is uninteresting on your part, feel free to close it.
Thanks

[bnoordhuis]

It sounds like the change is working as intended but cc @whitlockjc and @misterdjules, please reopen if you feel this needs more investigation.

[misterdjules]

Thank you for the heads up @bnoordhuis!

Without isolating the code that is responsible for driving the tests into self-contained code, it's going to be difficult to understand what's actually going on, and evaluate the extent of the problem.

@szdavid92 What was the fix for this problem in your project? Do you have a link to a commit on GitHub?