nodejs v8 memory gc allocation failure

Question

I am trying to profile nodejs v8 memory with a do nothing server. I used node-memwatch to get heap diff. I collect heap info before connecting and after connection tore down. I used node-memwatch. I tried 200 concurrent connections from client side.

Here is the gc trace after connection tore down.

can anyone help me to understand:

1.why are memory increasing ? after connections tore down, the server is absolutely doing nothing. shouldn't it suppose to always drop as garbages being collected ?
2. what is are those allocation failure ? How do I really interpret the trace here ?

 15802 ms: Mark-sweep 8.9 (45.0) -> 8.1 (45.0) MB, 58 ms [allocation failure] [GC in old space forced by flags].
 16144 ms: Mark-sweep 9.2 (45.0) -> 8.4 (45.0) MB, 53 ms [allocation failure] [GC in old space forced by flags].
 16495 ms: Mark-sweep 9.5 (45.0) -> 8.7 (46.0) MB, 60 ms [allocation failure] [GC in old space forced by flags].
 16837 ms: Mark-sweep 9.8 (46.0) -> 9.0 (46.0) MB, 56 ms [allocation failure] [GC in old space forced by flags].
 17197 ms: Mark-sweep 10.1 (46.0) -> 9.4 (46.0) MB, 62 ms [allocation failure] [GC in old space forced by flags].
 17905 ms: Mark-sweep 11.5 (46.0) -> 10.0 (47.0) MB, 74 ms [Runtime::PerformGC] [GC in old space forced by flags].                                                               
 18596 ms: Mark-sweep 12.2 (47.0) -> 10.7 (47.0) MB, 75 ms [Runtime::PerformGC] [GC in old space forced by flags].
 19315 ms: Mark-sweep 12.8 (47.0) -> 11.3 (48.0) MB, 83 ms [allocation failure] [GC in old space forced by flags].
 20035 ms: Mark-sweep 13.4 (48.0) -> 12.0 (49.0) MB, 90 ms [Runtime::PerformGC] [GC in old space forced by flags].
 21487 ms: Mark-sweep 16.0 (49.0) -> 13.2 (50.0) MB, 96 ms [Runtime::PerformGC] [GC in old space forced by flags].
 22950 ms: Mark-sweep 17.3 (50.0) -> 14.5 (52.0) MB, 116 ms [Runtime::PerformGC] [GC in old space forced by flags].
 24376 ms: Mark-sweep 18.8 (52.0) -> 15.9 (53.0) MB, 114 ms [allocation failure] [GC in old space forced by flags].
 25849 ms: Mark-sweep 19.9 (53.0) -> 17.2 (54.0) MB, 129 ms [Runtime::PerformGC] [GC in old space forced by flags].
 28773 ms: Mark-sweep 25.2 (54.0) -> 19.7 (57.0) MB, 149 ms [allocation failure] [GC in old space forced by flags].
 31725 ms: Mark-sweep 27.7 (57.0) -> 22.2 (59.0) MB, 172 ms [Runtime::PerformGC] [GC in old space forced by flags].
 34678 ms: Mark-sweep 30.2 (59.0) -> 24.7 (61.0) MB, 190 ms [Runtime::PerformGC] [GC in old space forced by flags].
 44045 ms: Mark-sweep 28.4 (61.0) -> 25.8 (63.0) MB, 180 ms [idle notification] [GC in old space forced by flags].
 44216 ms: Mark-sweep 25.8 (63.0) -> 25.8 (63.0) MB, 170 ms [idle notification] [GC in old space requested].
 57471 ms: Mark-sweep 26.9 (63.0) -> 25.8 (62.0) MB, 167 ms [Runtime::PerformGC] [GC in old space forced by flags].
 57651 ms: Mark-sweep 26.8 (62.0) -> 25.5 (62.0) MB, 160 ms [Runtime::PerformGC] [GC in old space forced by flags].
 57828 ms: Mark-sweep 26.5 (62.0) -> 25.5 (62.0) MB, 159 ms [Runtime::PerformGC] [GC in old space forced by flags].

Thanks,

Erik Corry · Accepted Answer · 2012-12-20 08:09:12Z

8

"allocation failure" sounds very dramatic, but there is no real failure involved. It just means that we allocated so much memory that it is time to do a GC to see if we can collect some memory.

It looks like you are running with the --gc-global flag ("GC forced by flags"). That's a bad idea for production, though it may be fine for narrowing down a problem when debugging.

I can't tell why your process is leaking. You may find the heap profiler useful. See https://github.com/felixge/node-memory-leak-tutorial

answered Dec 20, 2012 at 8:09

Erik Corry

6504 silver badges7 bronze badges

Sign up to request clarification or add additional context in comments.

1 Comment

haijin Over a year ago

Yes, I am using --gc-global and compact to ensure that all garbages collected before taking heap diff. That's minor. The question is why mem increases during gc ?

haijin · Accepted Answer · 2013-01-08 05:48:23Z

2

According to the code:

PrintF("%s %.1f (%.1f) -> %.1f (%.1f) MB, ",
       CollectorString(),
       static_cast<double>(start_object_size_) / MB,                                                                                    
       static_cast<double>(start_memory_size_) / MB, 
       SizeOfHeapObjects(),
       end_memory_size_mb);

Each line is one gc, when gc started,

start_object_size_ = heap_->SizeOfObjects();

In gc summary:

PrintF("total_size_before=%" V8_PTR_PREFIX "d ", start_object_size_);                                                                   
PrintF("total_size_after=%" V8_PTR_PREFIX "d ", heap_->SizeOfObjects());

As of why start_object_size_ increases in the time when my app is idle, I am guessing maybe during the gc, some objects got promoted to old space and caused object size in old space increased.

answered Jan 8, 2013 at 5:48

haijin

9482 gold badges11 silver badges17 bronze badges

1 Comment

bmacnaughton Over a year ago

this was useful to me even all these years later as it gave me a clue what to search for in the code code. here's the current code: github.com/nodejs/node/blob/…

Collectives™ on Stack Overflow

nodejs v8 memory gc allocation failure

2 Answers 2

1 Comment

1 Comment

Your Answer

Hot Network Questions

Collectives™ on Stack Overflow

2 Answers 2

1 Comment

1 Comment

Your Answer

Sign up or log in

Post as a guest

Related