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

[galniv]

• 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 }

[evanlucas]

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

[andrasq]

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.

[evanlucas]

Is that string something you could share?

[galniv]

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

[dfleury]

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.

[TimothyGu]

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

[mjsalinger]

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.

[bnoordhuis]

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

[andrasq]

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]

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]

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

[dfleury]

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.