Node: Out of memory issue plus weird heapUsed in node 8.1.4, does not occur on 6.11.1

Created on 20 Jul 2017  路  18Comments  路  Source: nodejs/node
  • Version: 8.1.4
  • Platform: Ubuntu

We recently attempted to upgrade to node 8.1.4. While testing our service with real data, each of the machines on which the service was deployed started crashing every few hours with an out-of-memory error. We also happened to log the result of process.memoryUsage() shortly before the crash on one of these machines, and noticed that the number for heapUsed seems unrealistic.

We downgraded the service to node 6.11.1, while keeping the exact same dependencies, and have not yet encountered any similar crashes. We'd appreciate any insights you may have on what could be causing this, and would be happy to provide any further information you require.

This is the error logged just before the crash:

<--- Last few GCs --->
[13312:0x41ef5a0] 16604020 ms: Mark-sweep 17592186044412.1 (56.4) -> 17592186044412.1 (56.4) MB, 36.2 / 0.0 ms  last resort 
<--- JS stacktrace --->
==== JS stack trace =========================================
Security context: 0x17102d81ba79 <JS Object>
    0: builtin exit frame: parse(this=0x17102d82cee9 <a JSON with map 0x7ecb210bec1>,0x2f670c198179 <Very long string[366930]>)
    1: /* anonymous */ [...path-to-file....:25] [pc=0x3576f1b40d57](this=0x394784c0a1c1 <JS Global Object>)
    2: _combinedTickCallback(aka _combinedTickCallback) [internal/process/next_tick.js:~93] [pc=0x3576f1a632c2](this=0x17102d802241 ...
FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - JavaScript heap out of memory
 1: node::Abort() [node]
 2: 0x13deffc [node]
 3: v8::Utils::ReportOOMFailure(char const*, bool) [node]
 4: v8::internal::V8::FatalProcessOutOfMemory(char const*, bool) [node]
 5: v8::internal::Factory::NewRawOneByteString(int, v8::internal::PretenureFlag) [node]
 6: v8::internal::Handle<v8::internal::String> v8::internal::JsonParser<true>::SlowScanJsonString<v8::internal::SeqOneByteString, unsigned char>(v8::internal::Handle<v8::internal::String>, int, int) [node]
 7: v8::internal::Handle<v8::internal::String> v8::internal::JsonParser<true>::SlowScanJsonString<v8::internal::SeqOneByteString, unsigned char>(v8::internal::Handle<v8::internal::String>, int, int) [node]
 8: v8::internal::Handle<v8::internal::String> v8::internal::JsonParser<true>::SlowScanJsonString<v8::internal::SeqOneByteString, unsigned char>(v8::internal::Handle<v8::internal::String>, int, int) [node]
 9: v8::internal::Handle<v8::internal::String> v8::internal::JsonParser<true>::SlowScanJsonString<v8::internal::SeqOneByteString, unsigned char>(v8::internal::Handle<v8::internal::String>, int, int) [node]
10: v8::internal::Handle<v8::internal::String> v8::internal::JsonParser<true>::SlowScanJsonString<v8::internal::SeqOneByteString, unsigned char>(v8::internal::Handle<v8::internal::String>, int, int) [node]
11: v8::internal::Handle<v8::internal::String> v8::internal::JsonParser<true>::SlowScanJsonString<v8::internal::SeqOneByteString, unsigned char>(v8::internal::Handle<v8::internal::String>, int, int) [node]
12: v8::internal::Handle<v8::internal::String> v8::internal::JsonParser<true>::SlowScanJsonString<v8::internal::SeqOneByteString, unsigned char>(v8::internal::Handle<v8::internal::String>, int, int) [node]
13: v8::internal::Handle<v8::internal::String> v8::internal::JsonParser<true>::SlowScanJsonString<v8::internal::SeqOneByteString, unsigned char>(v8::internal::Handle<v8::internal::String>, int, int) [node]
14: v8::internal::Handle<v8::internal::String> v8::internal::JsonParser<true>::SlowScanJsonString<v8::internal::SeqOneByteString, unsigned char>(v8::internal::Handle<v8::internal::String>, int, int) [node]
15: v8::internal::Handle<v8::internal::String> v8::internal::JsonParser<true>::ScanJsonString<false>() [node]
16: v8::internal::JsonParser<true>::ParseJsonValue() [node]
17: v8::internal::JsonParser<true>::ParseJsonObject() [node]
18: v8::internal::JsonParser<true>::ParseJsonValue() [node]
19: v8::internal::JsonParser<true>::ParseJsonObject() [node]
20: v8::internal::JsonParser<true>::ParseJsonValue() [node]
21: v8::internal::JsonParser<true>::ParseJsonObject() [node]
22: v8::internal::JsonParser<true>::ParseJsonValue() [node]
23: v8::internal::JsonParser<true>::ParseJsonObject() [node]
24: v8::internal::JsonParser<true>::ParseJsonValue() [node]
25: v8::internal::JsonParser<true>::ParseJson() [node]
26: v8::internal::Builtin_JsonParse(int, v8::internal::Object**, v8::internal::Isolate*) [node]
27: 0x3576ee5ab83d
Aborted (core dumped)

The result of the memoryUsage call mentioned above:

{ rss: 87867392,
  heapTotal: 497115136,
  heapUsed: 18446744073709396000,
  external: 18034382 }
V8 Engine question
Source
picture galniv

All 18 comments

I'd be curious to know how large the string that your are trying to parse is?

evanlucas picture evanlucas on 21 Jul 2017

370 kb; the [366930] part of the message is the string length.

The heapUsed is way too large to be real; it's 0xFFFFFFFFFFFDA020, which looks a lot like a 64-bit negative number interpreted as unsigned.

andrasq picture andrasq on 21 Jul 2017

Is that string something you could share?

evanlucas picture evanlucas on 21 Jul 2017

@evanlucas I'm afraid we cannot, but it's actually not a single 370kb string -- rather, that part of the code processes variable length strings, which can be anywhere from several kb to several mb in length. The other machines all crashed at the same part of the code, but while handling different length strings.

galniv picture galniv on 21 Jul 2017

I also noticed a strange behavior since 8.1.4 which still happens on 8.2.0 and 8.2.1
In my application I decided to stick with 8.1.3.
It didn't crash the process, however, the memory is leaking, cpu consumption increased 3x over the time the application is running and, the throughput was cut by half (40 req/s to 20 req/s).
I'm quite sure it's related to node because using older versions didn't seen to behave similarly.
My application is a service which receive jsons and render isomorphic components based on them. The payload size is limited to 500kb but I'm pretty sure it's receiving smaller payloads than that.
Each component is rendered inside an one-time use VM Context.
Last year, I saw a bad node version with similar issues. At that time, it was a bug of VM Context module version.
My app is running inside a docker container. Maybe the process isn't crashing because I'm using --max-semi-space-size=32 --max-old-space-size=128 to ensure it won't use the whole container's memory. Docker kills the container when it gets out of memory.

dfleury picture dfleury on 21 Jul 2017

@dfleury VM module performance is decreased in 8.1.4 because the decrease is temporarily necessary to fix an important security issue: https://nodejs.org/en/blog/vulnerability/july-2017-security-releases/. We are working with the V8 team to devise a solution that will re-enable snapshot support (which enhances performance of VM) in a secure way (#14171).

TimothyGu picture TimothyGu on 22 Jul 2017
👍1

We've seen this now in a completely seperate service, which crashed twice (with errors occuring in different places in the code).

Crash 1

<--- Last few GCs --->
[22994:0x3da85a0] 151710595 ms: Mark-sweep 17592186044414.3 (51.7) -> 17592186044414.3 (51.7) MB, 37.8 / 0.0 ms  last resort 
<--- JS stacktrace --->
==== JS stack trace =========================================
Security context: 0x3d9f2ec1ba79 <JS Object>
    0: builtin exit frame: parse(this=0x3d9f2ec2cee9 <a JSON with map 0x17f16ff0bec1>,0x2cc3bbf6f4c9 <Very long string[1736317]>)
    1: jsonDecode [<path to file>~29] [pc=0x11dcbe2dc876](this=0xae66a959019 <JS Global Object>,s=0x2cc3bbf6f4c9 <Very long string[1736317]>)
    2: _callback [<path to file>]...
FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - JavaScript heap out of memory
 1: node::Abort() [node]
 2: 0x13deffc [node]
 3: v8::Utils::ReportOOMFailure(char const*, bool) [node]
 4: v8::internal::V8::FatalProcessOutOfMemory(char const*, bool) [node]
 5: v8::internal::Factory::NewRawOneByteString(int, v8::internal::PretenureFlag) [node]
 6: v8::internal::Handle<v8::internal::String> v8::internal::JsonParser<false>::SlowScanJsonString<v8::internal::SeqOneByteString, unsigned char>(v8::internal::Handle<v8::internal::String>, int, int) [node]
 7: v8::internal::Handle<v8::internal::String> v8::internal::JsonParser<false>::SlowScanJsonString<v8::internal::SeqOneByteString, unsigned char>(v8::internal::Handle<v8::internal::String>, int, int) [node]
 8: v8::internal::Handle<v8::internal::String> v8::internal::JsonParser<false>::SlowScanJsonString<v8::internal::SeqOneByteString, unsigned char>(v8::internal::Handle<v8::internal::String>, int, int) [node]
 9: v8::internal::Handle<v8::internal::String> v8::internal::JsonParser<false>::SlowScanJsonString<v8::internal::SeqOneByteString, unsigned char>(v8::internal::Handle<v8::internal::String>, int, int) [node]
10: v8::internal::Handle<v8::internal::String> v8::internal::JsonParser<false>::SlowScanJsonString<v8::internal::SeqOneByteString, unsigned char>(v8::internal::Handle<v8::internal::String>, int, int) [node]
11: v8::internal::Handle<v8::internal::String> v8::internal::JsonParser<false>::SlowScanJsonString<v8::internal::SeqOneByteString, unsigned char>(v8::internal::Handle<v8::internal::String>, int, int) [node]
12: v8::internal::Handle<v8::internal::String> v8::internal::JsonParser<false>::SlowScanJsonString<v8::internal::SeqOneByteString, unsigned char>(v8::internal::Handle<v8::internal::String>, int, int) [node]
13: v8::internal::Handle<v8::internal::String> v8::internal::JsonParser<false>::SlowScanJsonString<v8::internal::SeqOneByteString, unsigned char>(v8::internal::Handle<v8::internal::String>, int, int) [node]
14: v8::internal::Handle<v8::internal::String> v8::internal::JsonParser<false>::SlowScanJsonString<v8::internal::SeqOneByteString, unsigned char>(v8::internal::Handle<v8::internal::String>, int, int) [node]
15: v8::internal::Handle<v8::internal::String> v8::internal::JsonParser<false>::SlowScanJsonString<v8::internal::SeqOneByteString, unsigned char>(v8::internal::Handle<v8::internal::String>, int, int) [node]
16: v8::internal::Handle<v8::internal::String> v8::internal::JsonParser<false>::ScanJsonString<false>() [node]
17: v8::internal::JsonParser<false>::ParseJsonValue() [node]
18: v8::internal::JsonParser<false>::ParseJsonObject() [node]
19: v8::internal::JsonParser<false>::ParseJsonValue() [node]
20: v8::internal::JsonParser<false>::ParseJsonObject() [node]
21: v8::internal::JsonParser<false>::ParseJsonValue() [node]
22: v8::internal::JsonParser<false>::ParseJsonObject() [node]
23: v8::internal::JsonParser<false>::ParseJsonValue() [node]
24: v8::internal::JsonParser<false>::ParseJson() [node]
25: v8::internal::Builtin_JsonParse(int, v8::internal::Object**, v8::internal::Isolate*) [node]
26: 0x11dcbbdab17d
Aborted (core dumped)

Crash 2

<--- Last few GCs --->
[16105:0x36e55a0] 147769851 ms: Mark-sweep 17592186044413.2 (47.3) -> 17592186044413.0 (47.3) MB, 33.6 / 0.0 ms  last resort 
<--- JS stacktrace --->
==== JS stack trace =========================================
Security context: 0x391a2f89ba79 <JS Object>
    3: evaluate [<root path>/node_modules/xpath.js/xpath.js:1209] [bytecode=0xc93a7aa9489 offset=140](this=0x211d45de90f9 <an XPath with map 0x2c6532b8c81>,c=0x211d45de8e09 <an XPathContext with map 0x2c6532b1539>)
    4: xpath(aka SelectNodes) [<root path>/xpath.js/xpath.js:4320] [pc=0x5e38b48979c](this=0x34f866b26b21 <an Object with map 0x38666966ccb9>,doc=0x1eea9bd0fea1 ...
FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - JavaScript heap out of memory
 1: node::Abort() [node]
 2: 0x13deffc [node]
 3: v8::Utils::ReportOOMFailure(char const*, bool) [node]
 4: v8::internal::V8::FatalProcessOutOfMemory(char const*, bool) [node]
 5: v8::internal::Factory::NewCode(v8::internal::CodeDesc const&, unsigned int, v8::internal::Handle<v8::internal::Object>, bool, bool, int, bool) [node]
 6: v8::internal::CodeGenerator::MakeCodeEpilogue(v8::internal::MacroAssembler*, v8::internal::EhFrameWriter*, v8::internal::CompilationInfo*, v8::internal::Handle<v8::internal::Object>) [node]
 7: v8::internal::FullCodeGenerator::MakeCode(v8::internal::CompilationInfo*, unsigned long) [node]
 8: v8::internal::FullCodegenCompilationJob::ExecuteJobImpl() [node]
 9: v8::internal::CompilationJob::ExecuteJob() [node]
10: 0xd408b8 [node]
11: 0xd418e8 [node]
12: 0xd41ba1 [node]
13: 0xd46929 [node]
14: v8::internal::Compiler::Compile(v8::internal::Handle<v8::internal::JSFunction>, v8::internal::Compiler::ClearExceptionFlag) [node]
15: v8::internal::Runtime_CompileLazy(int, v8::internal::Object**, v8::internal::Isolate*) [node]
16: 0x5e36f3040bd
Aborted (core dumped)

This is now three seperate crashes, coming from two different applications and multiple places within the code.

mjsalinger picture mjsalinger on 24 Jul 2017

Install llnode and poke around in the core dumps, perhaps it gives some clues. The second one suggests a lot of dynamic code generation (or perhaps merely lazy code generation at an inopportune time, in which case --nolazy might make a difference.)

bnoordhuis picture bnoordhuis on 24 Jul 2017

lldb versions 3.8, 4.0 and 5.0 segfault in GetMachine() when loading a non-localhost corefile. Turns out the debian 8.x pre-built lldb-3.5 still works, so I did not pursue this tangent further.

gdb lldb-4.0
(gdb) run ./node-v8.1.4 --core ./core
Starting program: /usr/bin/lldb-4.0 ./node-v8.1.4 --core ./core
...
Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x7fffed70f700 (LWP 12358)]
lldb_private::ArchSpec::GetMachine() const () at /build/llvm-toolchain-4.0-4.0~svn297204/tools/lldb/source/Core/ArchSpec.cpp:767
767     /build/llvm-toolchain-4.0-4.0~svn297204/tools/lldb/source/Core/ArchSpec.cpp: No such file or directory.
(gdb) where
#0  lldb_private::ArchSpec::GetMachine() const ()
    at /build/llvm-toolchain-4.0-4.0~svn297204/tools/lldb/source/Core/ArchSpec.cpp:767
#1  0x00007ffff65b9fcf in RegisterContextPOSIX_x86::RegisterContextPOSIX_x86(lldb_private::Thread&, unsigned int, lldb_private::RegisterInfoInterface*) ()
    at /build/llvm-toolchain-4.0-4.0~svn297204/tools/lldb/source/Plugins/Process/Utility/RegisterContextPOSIX_x86.cpp:324
...
(the backtrace at this point starts using 100% cpu and does not finish)

The specific function is

   766  llvm::Triple::ArchType ArchSpec::GetMachine() const {
   767    const CoreDefinition *core_def = FindCoreDefinition(m_core);
   768    if (core_def)
   769      return core_def->machine;
   770  
   771    return llvm::Triple::UnknownArch;
   772  }
andrasq picture andrasq on 27 Jul 2017

correction, lldb-3.5 only works to pull up the corefile and display the stack trace. It errors out when trying to examine variables (yes, there are two instances of process, not sure why):

(llnode) v8 findjsinstances process
0x00001fbe771e2bc9:<Object: process>
0x00002ddcb2307c19:<Object: process>
(llnode) v8 inspect 0x00002ddcb2307c19
error: error: warning: duplicate 'signed' declaration specifier
error: cannot combine with previous 'unsigned' declaration specifier
error: 1 errors parsing expression
andrasq picture andrasq on 31 Jul 2017

Non-local core files can be inspected with lldb-3.6, which has the parse error fixed.

To examine ubuntu-12.04.5 core files on ubuntu-12.04.5:

# install lldb
sudo apt-get install lldb-3.6

# build llnode
sudo apt-get install gcc-4.9
sudo apt-get install g++-4.9
git clone https://github.com/nodejs/llnode llnode.git
npm build llnode.git
cp llnode.git/out/Releas/obj.target/llnode.so .

# scan the core for memory ranges, needed to find objects
./llnode.git/scripts/readelf2segments.py core > core-ranges.out

# copy the core file and the node binary here
# run lldb with the llnode plugin, specifying the memory ranges
env LLNODE_RANGESFILE=core-ranges.out /usr/bin/lldb-3.6 --one-line 'plugin load llnode.so' --one-line "settings set prompt '(llnode) '" node-v8.1.4 --core core
andrasq picture andrasq on 8 Aug 2017

FYI,

since my last reply, the memory behavior and the application throughput has returned to normal.

Cpu doubled the usage from 15% to 30%. I'm asking myself if it might go lower in a future Node release or it can be considered the new expected usage.

dfleury picture dfleury on 17 Aug 2017

I am using mode 8.0 and I had the same issue before on aws using t2.large machine, so, I changed the type of the machine to m4.medium and add "--max-old-space-size=16000" to the node process, it solved my issue.

may215 picture may215 on 20 Aug 2017

I think I'm seeing the same behavior in node v7.10.1 and v8.5.0 with two nested for loops over two 10k elements array. Here is the full code:

hcombine.js

const fs = require('fs');

function capitalizeFirstLetter(string) {
  return string[0].toUpperCase() + string.slice(1);
}

const lines1 = fs.readFileSync(process.argv[2]).toString().split(/(\r?\n)+/).filter(x => ! /^(#|\s*)$/.test(x));
const lines2 = fs.readFileSync(process.argv[3]).toString().split(/(\r?\n)+/).filter(x => ! /^(#|\s*)$/.test(x));

// for (const line1 of lines1) {  -- crashed even sooner with the generator version
lines1.forEach(line1 => {
  // for (const line2 of lines2) {
  lines2.forEach(line2 => {
    const line1Cap = capitalizeFirstLetter(line1);
    const line2Cap = capitalizeFirstLetter(line2);
    const output = line1 + line2 + '\n'
        + line1 + line2Cap + '\n'
        + line1 + '-' + line2 + '\n'
        + line1 + '-' + line2Cap + '\n'
        + line1Cap + line2 + '\n'
        + line1Cap + line2Cap + '\n'
        + line1Cap + '-' + line2 + '\n'
        + line1Cap + '-' + line2Cap
    ;
    console.log(output);
  });
  console.log('\n');
});

Invoke as:

curl -s https://raw.githubusercontent.com/hermitdave/FrequencyWords/master/content/2016/ro/ro_50k.txt | head -10000 | cut -d ' ' -f1 > ro10k.txt
node --max_old_space_size=2000 hcombine.js ro10k.txt ro10k.txt > ro100M.txt

The output is

FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - JavaScript heap out of memory
 1: node::Abort() [node]
 2: 0x134e91c [node]
 3: v8::Utils::ReportOOMFailure(char const*, bool) [node]
 4: v8::internal::V8::FatalProcessOutOfMemory(char const*, bool) [node]
 5: v8::internal::Factory::NewFillerObject(int, bool, v8::internal::AllocationSpace) [node]
 6: v8::internal::Runtime_AllocateInTargetSpace(int, v8::internal::Object**, v8::internal::Isolate*) [node]
 7: 0x27338910ea5f
[1]    27733 abort (core dumped)  node --max_old_space_size=2000 hcombine.js ro10k.txt ro10k.txt >

What parameters do I need to pass to Node so it can run this loop?

dandv picture dandv on 14 Sep 2017

I'm fairly confident the .heapUsed bug has been addressed in recent V8 versions. The fix might already be in v8.5.0 and if not, it should be in v8.6.0 (assuming the V8 6.1 upgrade lands in that version.)

As to the "heap out of memory" questions, those are best directed to the help repo.

bnoordhuis picture bnoordhuis on 21 Sep 2017

verified that the problem does not recur with node-v8.9.1

andrasq picture andrasq on 3 Jan 2018
👎2

It happen in docker images 8-alpine (node-v8.10.0)

Security context: 0x417f56a57c1
1: _walk [0x261773c822d1 :~1041] [pc=0x3942fc739332](this=0x7bedf15a521 ,visitor=0x7bedf15a9e9 )
2: /* anonymous */ [0x261773c822d1 :801] [bytecode=0x2cf2e1d0b541 offset=17](this=0x2f5c0cc3d7b1 )
3: _walk [0x261773c822d1 :~799] [pc=0x3942fc7120a8](this=0x2f5c0...

FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - JavaScript heap out of memory
1: node::Abort() [node]
2: 0x11e73ec [node]
3: v8::Utils::ReportOOMFailure(char const, bool) [node]
4: v8::internal::V8::FatalProcessOutOfMemory(char const, bool) [node]
5: v8::internal::Factory::NewCode(v8::internal::CodeDesc const&, unsigned int, v8::internal::Handle, bool, int) [node]
6: v8::internal::CodeGenerator::MakeCodeEpilogue(v8::internal::TurboAssembler, v8::internal::EhFrameWriter, v8::internal::CompilationInfo, v8::internal::Handle) [node]
7: v8::internal::compiler::CodeGenerator::FinalizeCode() [node]
8: v8::internal::compiler::PipelineImpl::FinalizeCode() [node]
9: v8::internal::compiler::PipelineCompilationJob::FinalizeJobImpl() [node]
10: v8::internal::Compiler::FinalizeCompilationJob(v8::internal::CompilationJob) [node]
11: v8::internal::OptimizingCompileDispatcher::InstallOptimizedFunctions() [node]
12: v8::internal::StackGuard::HandleInterrupts() [node]
13: v8::internal::Runtime_StackGuard(int, v8::internal::Object*, v8::internal::Isolate) [node]
14: 0x3942fb3842fd

AllenBird picture AllenBird on 29 Aug 2018

verified that the problem does not recur with node-v8.9.1

you wrong, cause I'm facing same thing

kvelaro picture kvelaro on 4 Jul 2019
👍1
Was this page helpful?
0 / 5 - 0 ratings

Related issues

addaleax picture addaleax  路  3Comments
cong88 picture cong88  路  3Comments
jmichae3 picture jmichae3  路  3Comments
stevenvachon picture stevenvachon  路  3Comments
Brekmister picture Brekmister  路  3Comments