console.log - heap out of memory

[sinclairzx81]

The following code seems to result in a heap out of memory panic. Details below.

version

• os: ubuntu 16.04
• node: v10.12.0
• arch: x64

repro

let idx = 0
while(true) {
  console.log(idx++)
}

result

<omitted>
...
10110295
10110296
10110297
10110298

<--- Last few GCs --->

[27458:0x4065d90]   149938 ms: Scavenge 1393.5 (1423.7) -> 1392.7 (1424.2) MB, 4.0 / 0.0 ms  (average mu = 0.236, current mu = 0.207) allocation failure 
[27458:0x4065d90]   149958 ms: Scavenge 1393.7 (1424.2) -> 1392.9 (1424.7) MB, 3.6 / 0.0 ms  (average mu = 0.236, current mu = 0.207) allocation failure 
[27458:0x4065d90]   149972 ms: Scavenge 1393.8 (1424.7) -> 1393.0 (1425.7) MB, 2.4 / 0.0 ms  (average mu = 0.236, current mu = 0.207) allocation failure 


<--- JS stacktrace --->

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

    0: ExitFrame [pc: 0x3d579c65be1d]
    1: StubFrame [pc: 0x3d579c634fbf]
Security context: 0x15c8a491e6e1 <JSObject>
    2: writeOrBuffer(aka writeOrBuffer) [0x45e96d023f9] [_stream_writable.js:~360] [pc=0x3d579c666367](this=0x0c9d5af826f1 <undefined>,stream=0x045e96d3d5c9 <WriteStream map = 0x2ead0884f411>,state=0x045e96d3d499 <WritableState map = 0x2ead0884ec29>,isBuf=0x0c9d5af829a1 <false>,chunk=0x28e2cad9ef41 <String[19]\: \x1b[33m...

FATAL ERROR: Ineffective mark-compacts near heap limit Allocation failed - JavaScript heap out of memory
 1: 0x8daaa0 node::Abort() [node]
 2: 0x8daaec  [node]
 3: 0xad79ae v8::Utils::ReportOOMFailure(v8::internal::Isolate*, char const*, bool) [node]
 4: 0xad7be4 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [node]
 5: 0xece9e2  [node]
 6: 0xeceae8 v8::internal::Heap::CheckIneffectiveMarkCompact(unsigned long, double) [node]
 7: 0xedac12 v8::internal::Heap::PerformGarbageCollection(v8::internal::GarbageCollector, v8::GCCallbackFlags) [node]
 8: 0xedb5d4 v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [node]
 9: 0xede241 v8::internal::Heap::AllocateRawWithRetryOrFail(int, v8::internal::AllocationSpace, v8::internal::AllocationAlignment) [node]
10: 0xea7564 v8::internal::Factory::NewFillerObject(int, bool, v8::internal::AllocationSpace) [node]
11: 0x114bc12 v8::internal::Runtime_AllocateInNewSpace(int, v8::internal::Object**, v8::internal::Isolate*) [node]
12: 0x3d579c65be1d 
Aborted

[Hakerh400]

It's because console.log uses internal buffers that can be deallocated only when the event loop takes control again. It is intended behavior I think.

Replacing console.log(idx++) with

require('fs').writeSync(process.stdout.fd, (idx++) + '\n');

doesn't cause crash.

[joyeecheung]

This should be expected, the GC never gets a chance to kick in in a while(true) dead loop, so it will eventually crash. Replacing console.log() with fs.writeSync() will not prevent the crash, but because fs.writeSync() is a much less complicated method than console.log() (hence much less heap allocated internals), the crash will come much slower.

[Hakerh400]

@joyeecheung Just to make it clear: the issue in the OP is not related to GC being unable to kick in a while loop, but to process.stdout.write being asynchronous. console.log writes to process.stdout asynchronously, so the buffers it allocates stay in the memory. However fs.writeSync skips process.stdout.write and writes directly to the console's stdout, making the allocated buffers available for GC to be cleaned up. fs.writeSync doesn't leak memory.

[sinclairzx81]

@Hakerh400 @joyeecheung thanks for joining in. I'll close this one off I think. I did find it somewhat surprising that while(true) { console.log('hello world') } would eventually panic a node process (i'd have assumed a GC collect before hand), but perhaps this is the nature of JS/v8.

Have tested node versions all the way back to 0.6 so assume this to be a known caveat.

Thank tho.