Skip to content

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

Description

@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).

Activity

  1. bnoordhuis commented on Jul 25, 2016

    @bnoordhuis
    Member

    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?

  2. added
    memoryIssues and PRs related to Node.js memory management or memory footprint.
    on Jul 25, 2016
  3. dszakallas commented on Jul 25, 2016

    @dszakallas
    ContributorAuthor

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

  4. bnoordhuis commented on Jul 25, 2016

    @bnoordhuis
    Member

    Thanks. Does upping --max_old_space_size make a difference?

  5. dszakallas commented on Jul 26, 2016

    @dszakallas
    ContributorAuthor

    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

  6. bnoordhuis commented on Jul 26, 2016

    @bnoordhuis
    Member

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

  7. misterdjules commented on Jul 26, 2016

    @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?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    memoryIssues and PRs related to Node.js memory management or memory footprint.

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions