Configuring v8's memory management to be smart

Question

We run an XMPP server on node.js, on a machine with around 3.8 GB RAM. Here are the command line parameters we pass while invoking node : /opt/node/bin/node --max-old-space-size=3000 --trace-gc --trace-gc-verbose main.js

However, we frequently have to see more than 10 second gc pauses in the process ( sometimes as much as more than 1 minute gc pauses, where our server is doing nothing but running GC ). When this happens, our process is at it's normal memory consumption : around 1 GB heap usage. There is around 2 GB or free space available for the process, but the process just does not use it and spends a minute trying to free memory.

Looking at the gc trace given by --trace-gc-verbose option, it looks like around 2 GB free space is marked as "Large object space", and is not used, as there are not that many large objects. And though the process is in dire need of more memory for "Old pointers" and "Old data space", this free memory from "Large object space" is not used.

Here is the trace left by gc during one of those times where there was a long gc pause in the process :

    

91635809 ms: Mark-sweep 968.8 (1039.0) -> 958.5 (1038.0) MB, 1 / 410 ms (+ 2287 ms in 79 steps since start of marking, biggest step 140.227051 ms) [idle notification: finalize incremental] [GC in old space requested].
Memory allocator,   used: 1088446464, available: 2124390400
New space,          used:      192, available:  8388416
Old pointers,       used: 633992112, available: 10460240, waste:        0
Old data space,     used: 315819248, available:   149776, waste:        0
Code space,         used:  5867936, available:  1271392, waste:        0
Map space,          used: 10257976, available:  6384072, waste:        0
Cell space,         used:   175936, available:   954304, waste:        0
Large object space, used: 51413600, available: 2123325184
91636499 ms: Scavenge 965.5 (1038.0) -> 964.6 (1038.0) MB, 17 ms (+ 109 ms in 10 steps since last GC) [Runtime::PerformGC].
Memory allocator,   used: 1088446464, available: 2124390400
New space,          used:    41256, available:  2055896
Old pointers,       used: 628458688, available: 15993664, waste:        0
Old data space,     used: 315821792, available:   147232, waste:        0
Code space,         used:  5904256, available:  1235072, waste:        0
Map space,          used: 10263072, available:  6378976, waste:        0
Cell space,         used:   175936, available:   954304, waste:        0
Large object space, used: 51413600, available: 2123325184
91637979 ms: Scavenge 966.6 (1038.0) -> 964.7 (1038.0) MB, 1 ms (+ 1404 ms in 43 steps since last GC) [Runtime::PerformGC].
Memory allocator,   used: 1088446464, available: 2124390400
New space,          used:    76736, available:  2020416
Old pointers,       used: 628458688, available: 15993664, waste:        0
Old data space,     used: 315845520, available:   123504, waste:        0
Code space,         used:  5980576, available:  1158752, waste:        0
Map space,          used: 10271416, available:  6370632, waste:        0
Cell space,         used:   175936, available:   954304, waste:        0
Large object space, used: 51413600, available: 2123325184
91639088 ms: Mark-sweep 965.2 (1038.0) -> 935.8 (1038.0) MB, 1 / 369 ms (+ 2235 ms in 71 steps since start of marking, biggest step 69.053955 ms) [idle notification: finalize incremental] [GC in old space requested].
Memory allocator,   used: 1088446464, available: 2124390400
New space,          used:      168, available:  2096984
Old pointers,       used: 641099768, available:  3352584, waste:        0
Old data space,     used: 315820152, available:   148872, waste:        0
Code space,         used:  5862976, available:  1276352, waste:        0
Map space,          used: 10256744, available:  6385304, waste:        0
Cell space,         used:   175936, available:   954304, waste:        0
Large object space, used: 51413600, available: 2123325184
91640987 ms: Scavenge 966.4 (1038.0) -> 964.5 (1038.0) MB, 1 ms (+ 1275 ms in 36 steps since last GC) [allocation failure].
Memory allocator,   used: 1088446464, available: 2124390400
New space,          used:   100944, available:  1996208
Old pointers,       used: 627957504, available: 16494848, waste:        0
Old data space,     used: 315830536, available:   138488, waste:        0
Code space,         used:  5951200, available:  1188128, waste:        0
Map space,          used: 10266376, available:  6375672, waste:        0
Cell space,         used:   175936, available:   954304, waste:        0
Large object space, used: 51413600, available: 2123325184
91641560 ms: Scavenge 966.5 (1038.0) -> 964.8 (1038.0) MB, 2 ms (+ 481 ms in 29 steps since last GC) [Runtime::PerformGC].
Memory allocator,   used: 1088446464, available: 2124390400
New space,          used:   180712, available:  1916440
Old pointers,       used: 627957504, available: 16494848, waste:        0
Old data space,     used: 315871432, available:    97592, waste:        0
Code space,         used:  6019392, available:  1119936, waste:        0
Map space,          used: 10269848, available:  6372200, waste:        0
Cell space,         used:   176192, available:   954048, waste:        0
Large object space, used: 51413600, available: 2123325184
91642589 ms: Mark-sweep 965.9 (1038.0) -> 947.7 (1038.0) MB, 1 / 371 ms (+ 2369 ms in 89 steps since start of marking, biggest step 67.302002 ms) [idle notification: finalize incremental] [GC in old space requested].
Memory allocator,   used: 1088446464, available: 2124390400
New space,          used:      264, available:  2096888
Old pointers,       used: 639592840, available:  4859512, waste:        0
Old data space,     used: 315849408, available:   119616, waste:        0
Code space,         used:  5862976, available:  1276352, waste:        0
Map space,          used: 10257136, available:  6384912, waste:        0
Cell space,         used:   175936, available:   954304, waste:        0
Large object space, used: 51413600, available: 2123325184
91643688 ms: Scavenge 966.4 (1038.0) -> 964.6 (1038.0) MB, 5 ms (+ 356 ms in 21 steps since last GC) [Runtime::PerformGC].
Memory allocator,   used: 1088446464, available: 2124390400
New space,          used:   144088, available:  1953064
Old pointers,       used: 627748368, available: 16703984, waste:        0
Old data space,     used: 315864504, available:   104520, waste:        0
Code space,         used:  5990240, available:  1149088, waste:        0
Map space,          used: 10264248, available:  6377800, waste:        0
Cell space,         used:   176192, available:   954048, waste:        0
Large object space, used: 51413600, available: 2123325184
91645276 ms: Scavenge 966.5 (1038.0) -> 964.8 (1039.0) MB, 2 ms (+ 1520 ms in 46 steps since last GC) [allocation failure].
Memory allocator,   used: 1089495040, available: 2123341824
New space,          used:   108192, available:  1988960
Old pointers,       used: 627748368, available: 16703984, waste:        0
Old data space,     used: 315978760, available:  1022200, waste:        0
Code space,         used:  6039008, available:  1100320, waste:        0
Map space,          used: 10274216, available:  6367832, waste:        0
Cell space,         used:   176192, available:   954048, waste:        0
Large object space, used: 51413600, available: 2122276608
91645577 ms: Scavenge 966.6 (1039.0) -> 965.8 (1039.0) MB, 3 ms (+ 263 ms in 23 steps since last GC) [allocation failure].
Memory allocator,   used: 1089495040, available: 2123341824
New space,          used:   516168, available:  1580984
Old pointers,       used: 627843088, available: 16609264, waste:        0
Old data space,     used: 316550680, available:   450280, waste:        0
Code space,         used:  6039008, available:  1100320, waste:        0
Map space,          used: 10275280, available:  6366768, waste:        0
Cell space,         used:   176192, available:   954048, waste:        0
Large object space, used: 51413600, available: 2122276608
91645645 ms: Scavenge 967.3 (1039.0) -> 966.8 (1039.0) MB, 5 ms (+ 8 ms in 16 steps since last GC) [allocation failure].
Memory allocator,   used: 1089495040, available: 2123341824
New space,          used:  1012304, available:  3182000               
Old pointers,       used: 627968088, available: 16484264, waste:        0
Old data space,     used: 316947304, available:    53656, waste:        0
Code space,         used:  6039008, available:  1100320, waste:        0
Map space,          used: 10275280, available:  6366768, waste:        0
Cell space,         used:   176192, available:   954048, waste:        0
Large object space, used: 51413600, available: 2122276608
91645948 ms: Scavenge 969.8 (1039.0) -> 968.6 (1041.0) MB, 9 ms (+ 188 ms in 35 steps since last GC) [allocation failure].
Memory allocator,   used: 1091592192, available: 2121244672
New space,          used:  1032320, available:  3161984
Old pointers,       used: 628219008, available: 16233344, waste:        0
Old data space,     used: 318537928, available:   526904, waste:        0
Code space,         used:  6039264, available:  1100064, waste:        0
Map space,          used: 10276232, available:  6365816, waste:        0
Cell space,         used:   176192, available:   954048, waste:        0
Large object space, used: 51413600, available: 2120179456
91646093 ms: Scavenge 971.6 (1041.0) -> 970.5 (1042.0) MB, 13 ms (+ 36 ms in 30 steps since last GC) [Runtime::PerformGC].
Memory allocator,   used: 1092640768, available: 2120196096
New space,          used:  2044456, available:  6344152
Old pointers,       used: 628437424, available: 16014928, waste:        0
Old data space,     used: 319366376, available:   730392, waste:        0
Code space,         used:  6039264, available:  1100064, waste:        0
Map space,          used: 10276232, available:  6365816, waste:        0
Cell space,         used:   176192, available:   954048, waste:        0
Large object space, used: 51413600, available: 2119130880
91646306 ms: Scavenge 976.5 (1042.0) -> 974.7 (1044.0) MB, 1 / 14 ms (+ 114 ms in 67 steps since last GC) [allocation failure].
Memory allocator,   used: 1094737920, available: 2118098944
New space,          used:  2064112, available:  6324496
Old pointers,       used: 630440024, available: 14012328, waste:        0
Old data space,     used: 321653384, available:   507256, waste:        0
Code space,         used:  6055936, available:  1083392, waste:        0
Map space,          used: 10278192, available:  6363856, waste:        0
Cell space,         used:   176192, available:   954048, waste:        0
Large object space, used: 51413600, available: 2117033728
91646386 ms: Scavenge 980.6 (1044.0) -> 979.2 (1046.0) MB, 12 ms (+ 10 ms in 64 steps since last GC) [allocation failure].
Memory allocator,   used: 1096835072, available: 2116001792
New space,          used:  4127736, available: 12649480
Old pointers,       used: 631182984, available: 13269368, waste:        0
Old data space,     used: 323586008, available:   638504, waste:        0
Code space,         used:  6055936, available:  1083392, waste:        0
Map space,          used: 10278192, available:  6363856, waste:        0
Cell space,         used:   176192, available:   954048, waste:        0
Large object space, used: 51413600, available: 2114936576
Limited new space size due to high promotion rate: 1 MB
91646810 ms: Mark-sweep 979.2 (1046.0) -> 973.2 (1049.0) MB, 1 / 422 ms (+ 2500 ms in 303 steps since start of marking, biggest step 0.122070 ms) [StackGuard GC request] [GC in old space requested].
Memory allocator,   used: 1099980800, available: 2112856064
New space,          used:      192, available:  1048384
Old pointers,       used: 636894816, available:  9621408, waste:        0
Old data space,     used: 325256448, available:        0, waste:        0
Code space,         used:  5860928, available:  1278400, waste:        0
Map space,          used: 10257976, available:  6384072, waste:        0
Cell space,         used:   176192, available:   954048, waste:        0
Large object space, used: 51413600, available: 2111790848
91646825 ms: Scavenge 974.2 (1049.0) -> 979.0 (1049.0) MB, 7 ms [allocation failure].
Memory allocator,   used: 1099980800, available: 2112856064
New space,          used:   257960, available:   790616
Old pointers,       used: 635948464, available: 10567760, waste:        0
Old data space,     used: 325256448, available:        0, waste:        0
Code space,         used:  5873440, available:  1265888, waste:        0
Map space,          used: 10258536, available:  6383512, waste:        0
Cell space,         used:   176192, available:   954048, waste:        0
Large object space, used: 51413600, available: 2111790848
91646834 ms: Scavenge 979.7 (1049.0) -> 980.0 (1049.0) MB, 2 ms [allocation failure].
Memory allocator,   used: 1099980800, available: 2112856064
New space,          used:   257968, available:   790608
Old pointers,       used: 635671408, available: 10844816, waste:        0
Old data space,     used: 325256448, available:        0, waste:        0
Code space,         used:  5873440, available:  1265888, waste:        0
Map space,          used: 10258536, available:  6383512, waste:        0
Cell space,         used:   176192, available:   954048, waste:        0
Large object space, used: 51413600, available: 2111790848
91646842 ms: Scavenge 980.7 (1049.0) -> 980.6 (1049.0) MB, 2 ms [allocation failure].
Memory allocator,   used: 1099980800, available: 2112856064
New space,          used:   257960, available:   790616
Old pointers,       used: 635493872, available: 11022352, waste:        0
Old data space,     used: 325256448, available:        0, waste:        0
Code space,         used:  5873440, available:  1265888, waste:        0
Map space,          used: 10258536, available:  6383512, waste:        0
Cell space,         used:   176192, available:   954048, waste:        0
Large object space, used: 51413600, available: 2111790848
91646849 ms: Scavenge 981.3 (1049.0) -> 981.2 (1049.0) MB, 1 ms [allocation failure].
Memory allocator,   used: 1099980800, available: 2112856064
New space,          used:   257968, available:   790608
Old pointers,       used: 635981640, available: 10534584, waste:        0
Old data space,     used: 325256448, available:        0, waste:        0
Code space,         used:  5873440, available:  1265888, waste:        0
Map space,          used: 10258536, available:  6383512, waste:        0
Cell space,         used:   176192, available:   954048, waste:        0
Large object space, used: 51413600, available: 2111790848
91646863 ms: Scavenge 981.9 (1049.0) -> 981.6 (1051.0) MB, 1 ms [allocation failure].
Memory allocator,   used: 1102077952, available: 2110758912
New space,          used:   257960, available:   790616
Old pointers,       used: 637013288, available: 10534872, waste:        0
Old data space,     used: 326288384, available:        0, waste:        0
Code space,         used:  5873440, available:  1265888, waste:        0
Map space,          used: 10258536, available:  6383512, waste:        0
Cell space,         used:   176192, available:   954048, waste:        0
Large object space, used: 51413600, available: 2109693696
91651639 ms: Mark-sweep 981.6 (1051.0) -> 924.7 (1051.0) MB, 1 / 4775 ms [last resort gc].
Memory allocator,   used: 1102077952, available: 2110758912
New space,          used:       96, available:  1048480
Old pointers,       used: 626794192, available: 20753968, waste:        0
Old data space,     used: 275760200, available: 50528184, waste:        0
Code space,         used:  6182208, available:   957120, waste:        0
Map space,          used: 10257808, available:  6384240, waste:        0
Cell space,         used:   176192, available:   954048, waste:        0
Large object space, used: 51413600, available: 2109693696
91663655 ms: Mark-sweep 924.7 (1051.0) -> 924.7 (1050.0) MB, 1 / 12015 ms [last resort gc].
Memory allocator,   used: 1101029376, available: 2111807488
New space,          used:        0, available:  1048576
Old pointers,       used: 626169464, available: 21378696, waste:        0
Old data space,     used: 275759960, available: 49496488, waste:        0
Code space,         used:  5850624, available:  1288704, waste:        0
Map space,          used: 10257808, available:  6384240, waste:                 

Is there any tuning that I can do to better configure v8's memory management ? Any ideas on what might help here ?

Answer 1

I think it is a limitation of V8. It does not use more than 1.7 GB of RAM on 64 bit machines. Quote from FAQ:

Currently, by default v8 has a memory limit of 512mb on 32-bit systems, and 1gb on 64-bit systems. The limit can be raised by setting --max-old-space-size to a maximum of ~1gb (32-bit) and ~1.7gb (64-bit), but it is recommended that you split your single process into several workers if you are hitting memory limits.

So following this you are hitting the maximum memory limits and the 10 second pause due to garbage collection is a big worry. You should consider running garbage collector periodically/when idle to avoid hitting the limit and facing long delays.

Parameters which you can pass to help the situation are : (Check this blog)

• --nouse-idle-notification which prevents running GC constantly and
• --expose-gc which will allow you to run GC from your code.

Most importantly debug your code to remove memory leaks. Use these package to find them in your code:

• nodetime
• node-inspector