Search code examples
node.jsmemorygarbage-collectionv8

nodejs v8 memory gc allocation failure


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,


Solution

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