You are using object representation that is not really GC friendly. Split you array into pieces (build B-tree like data structure) and you will see GC pauses that are smaller by orders of magnitude. Vyacheslav Egorov
On Wed, Nov 7, 2012 at 2:35 AM, darcy <[email protected]> wrote: > > I've did a test for performance issues caused by GC and memory consumption. > My test run on linux, node v0.8.5 > > the code: >> >> var obj_num = 5000000; >> >> var fill = {} >> >> for (var i = obj_num; i >= 0; i--) { >> >> fill["fill string*******************" + i] = "fill string" + i; >> >> }; >> >> setInterval(function () { >> >> fill[0] = "something" + Date.now(); >> >> }, 1); > > > if run by "node --trace_gc gc_test.js", the output is: > > 9407594 ms: Scavenge 849.0 (894.0) -> 848.1 (894.0) MB, 0 ms > [Runtime::PerformGC]. > 9418468 ms: Scavenge 849.0 (894.0) -> 848.1 (894.0) MB, 0 ms > [Runtime::PerformGC]. > 9429360 ms: Scavenge 849.0 (894.0) -> 848.1 (894.0) MB, 0 ms > [Runtime::PerformGC]. > 9440165 ms: Scavenge 849.0 (894.0) -> 848.1 (894.0) MB, 0 ms > [Runtime::PerformGC]. > 9450968 ms: Scavenge 849.0 (894.0) -> 848.1 (894.0) MB, 0 ms > [Runtime::PerformGC]. > 9453661 ms: Mark-sweep 848.1 (894.0) -> 848.1 (894.0) MB, 484 ms (+ 1385 ms > in 3 steps since start of m > arking, biggest step 1152.330811 ms) [idle notification: finalize > incremental] [GC in old space requeste > d]. > 9455521 ms: Mark-sweep 848.1 (894.0) -> 848.0 (894.0) MB, 470 ms (+ 1388 ms > in 3 steps since start of m > arking, biggest step 1148.824219 ms) [idle notification: finalize > incremental] [GC in old space requeste > d]. > 9457355 ms: Mark-sweep 848.1 (894.0) -> 848.0 (894.0) MB, 463 ms (+ 1360 ms > in 3 steps since start of m > arking, biggest step 1132.174072 ms) [idle notification: finalize > incremental] [GC in old space requeste > d]. > 9459202 ms: Mark-sweep 848.1 (894.0) -> 848.0 (894.0) MB, 463 ms (+ 1372 ms > in 3 steps since start of m > arking, biggest step 1139.920898 ms) [idle notification: finalize > incremental] [GC in old space requeste > d]. > 9461050 ms: Mark-sweep 848.1 (894.0) -> 848.0 (894.0) MB, 467 ms (+ 1371 ms > in 3 steps since start of m > arking, biggest step 1136.500977 ms) [idle notification: finalize > incremental] [GC in old space requeste > d]. > 9464581 ms: Mark-sweep 848.1 (894.0) -> 848.0 (894.0) MB, 3521 ms [idle > notification: finalize idle rou > nd] [GC in old space requested]. > 9468118 ms: Mark-sweep 848.1 (894.0) -> 848.0 (894.0) MB, 3527 ms [idle > notification: finalize idle rou > nd] [GC in old space requested]. > 9478934 ms: Scavenge 849.0 (894.0) -> 848.1 (894.0) MB, 0 ms > [Runtime::PerformGC]. > 9489861 ms: Scavenge 849.0 (894.0) -> 848.1 (894.0) MB, 0 ms > [Runtime::PerformGC]. > 9500980 ms: Scavenge 849.0 (894.0) -> 848.1 (894.0) MB, 0 ms > [Runtime::PerformGC]. > 9511772 ms: Scavenge 849.0 (894.0) -> 848.1 (894.0) MB, 0 ms > [Runtime::PerformGC]. > 9522651 ms: Scavenge 849.0 (894.0) -> 848.1 (894.0) MB, 0 ms > [Runtime::PerformGC]. > 9524948 ms: Mark-sweep 848.1 (894.0) -> 848.1 (894.0) MB, 479 ms (+ 1350 ms > in 3 steps since start of marking, biggest step 1121.382812 ms) [idle > notification: finalize incremental] [GC in old space requested]. > 9526773 ms: Mark-sweep 848.1 (894.0) -> 848.0 (894.0) MB, 462 ms (+ 1361 ms > in 3 steps since start of marking, biggest step 1132.158936 ms) [idle > notification: finalize incremental] [GC in old space requested]. > 9528606 ms: Mark-sweep 848.1 (894.0) -> 848.0 (894.0) MB, 468 ms (+ 1353 ms > in 3 steps since start of marking, biggest step 1121.354980 ms) [idle > notification: finalize incremental] [GC in old space requested]. > 9530459 ms: Mark-sweep 848.1 (894.0) -> 848.0 (894.0) MB, 467 ms (+ 1374 ms > in 3 steps since start of marking, biggest step 1143.323975 ms) [idle > notification: finalize incremental] [GC in old space requested]. > 9532307 ms: Mark-sweep 848.1 (894.0) -> 848.0 (894.0) MB, 467 ms (+ 1370 ms > in 3 steps since start of marking, biggest step 1139.680908 ms) [idle > notification: finalize incremental] [GC in old space requested]. > 9535905 ms: Mark-sweep 848.1 (894.0) -> 848.0 (894.0) MB, 3587 ms [idle > notification: finalize idle round] [GC in old space requested]. > 9539484 ms: Mark-sweep 848.1 (894.0) -> 848.0 (894.0) MB, 3569 ms [idle > notification: finalize idle round] [GC in old space requested]. > 9550287 ms: Scavenge 849.0 (894.0) -> 848.1 (894.0) MB, 0 ms > [Runtime::PerformGC]. > 9561110 ms: Scavenge 849.0 (894.0) -> 848.1 (894.0) MB, 0 ms > [Runtime::PerformGC]. > > it indicated that gc used several seconds every tens of seconds. As you > know, In this period no user code is executed, and the cpu usage is about > 100%. > > if run by "node --trace_gc --nouse_idle_notification gc_test.js", the output > is like this: > > 9284693 ms: Scavenge 850.1 (894.0) -> 848.1 (894.0) MB, 0 ms > [Runtime::PerformGC]. > 9306457 ms: Scavenge 850.1 (894.0) -> 848.1 (894.0) MB, 0 ms > [Runtime::PerformGC]. > 9328158 ms: Scavenge 850.1 (894.0) -> 848.1 (894.0) MB, 0 ms > [Runtime::PerformGC]. > 9349766 ms: Scavenge 850.1 (894.0) -> 848.1 (894.0) MB, 0 ms > [Runtime::PerformGC]. > 9371736 ms: Scavenge 850.1 (894.0) -> 848.1 (894.0) MB, 0 ms > [Runtime::PerformGC]. > 9393432 ms: Scavenge 850.1 (894.0) -> 848.1 (894.0) MB, 0 ms > [Runtime::PerformGC]. > 9415037 ms: Scavenge 850.1 (894.0) -> 848.1 (894.0) MB, 0 ms > [Runtime::PerformGC]. > 9436695 ms: Scavenge 850.1 (894.0) -> 848.1 (894.0) MB, 0 ms > [Runtime::PerformGC]. > 9458344 ms: Scavenge 850.1 (894.0) -> 848.1 (894.0) MB, 0 ms > [Runtime::PerformGC] > > No heavy gc is executed in 9458344ms, I didn't do any longer test. > > if run by "node --trace_gc --nouse_idle_notification > --max_old_space_size=500 gc_test.js", we can see in the log of previous > case, user code needs more than 500MB. the output is like this: > > Marking speed increased to 76 > Speed up marking because of low space left > Postponing speeding up marking until marking starts > 82169 ms: Mark-sweep 537.8 (577.0) -> 537.8 (578.0) MB, 705 ms (+ 888 ms > in 10 steps since start of m > arking, biggest step 664.453857 ms) [StackGuard GC request] [GC in old space > requested]. > Speed up marking because of low space left > Marking speed increased to 3 > Speed up marking because of low space left > Marking speed increased to 6 > Speed up marking because of low space left > Marking speed increased to 10 > Speed up marking because of low space left > Speed up marking because marker was not keeping up > Marking speed increased to 15 > Speed up marking because of low space left > Speed up marking because marker was not keeping up > Marking speed increased to 22 > Speed up marking because of low space left > Speed up marking because marker was not keeping up > Marking speed increased to 31 > Speed up marking because of low space left > Speed up marking because marker was not keeping up > Marking speed increased to 42 > Speed up marking because of low space left > Speed up marking because marker was not keeping up > Marking speed increased to 57 > Speed up marking because of low space left > Speed up marking because marker was not keeping up > Marking speed increased to 76 > Speed up marking because of low space left > Postponing speeding up marking until marking starts > 83766 ms: Mark-sweep 538.6 (578.0) -> 538.6 (579.0) MB, 706 ms (+ 882 ms > in 10 steps since start of marking, biggest step 646.981934 ms) [StackGuard > GC request] [GC in old space requested]. > Speed up marking because of low space left > Marking speed increased to 3 > > It indicated that the program is always busy with GC, and with cpu usage > 100%, meanwhile there's little chance to execute user code. Default > max_old_space_size is about 1900MB, so if user code needs more memory than > this, will be blocked by gc. > > So, the impact of --nouse_idle_notification is more than acceptable, with a > block to program for several seconds every tens of seconds. I read the > relative source code of node and v8, and found this: > > // v8, heap.cc > bool Heap::IdleNotification(int hint) { > // Hints greater than this value indicate that > // the embedder is requesting a lot of GC work. > const int kMaxHint = 1000; > // Minimal hint that allows to do full GC. > const int kMinHintForFullGC = 100; > > ... > > if (remaining_mark_sweeps <= 2 && hint >= kMinHintForFullGC) { > CollectAllGarbage(kReduceMemoryFootprintMask, > "idle notification: finalize idle round"); > } else { > incremental_marking()->Start(); > } > } > > because there's "idle notification: finalize idle round" in the log, and > there's only one apperance in v8 src, so that CollectAllGarbage() is called > in IdleNotification. Pay attention to the param "hint", node called > V8::IdleNotification() with default param value 1000, which is the max, > means most aggressive. I changed the value to 1: > > // in node.cc > static void Idle(uv_idle_t* watcher, int status) { > assert((uv_idle_t*) watcher == &gc_idle); > > if (V8::IdleNotification(1)) { > uv_idle_stop(&gc_idle); > StopGCTimer(); > } > } > > rebuild node and run by "node --trace_gc gc_test.js", the output is: > > 7443012 ms: Scavenge 849.1 (894.0) -> 848.1 (894.0) MB, 0 ms > [Runtime::PerformGC]. > 7453843 ms: Scavenge 849.1 (894.0) -> 848.1 (894.0) MB, 0 ms > [Runtime::PerformGC]. > 7464650 ms: Scavenge 849.1 (894.0) -> 848.1 (894.0) MB, 0 ms > [Runtime::PerformGC]. > 7475521 ms: Scavenge 849.1 (894.0) -> 848.1 (894.0) MB, 0 ms > [Runtime::PerformGC]. > 7486301 ms: Scavenge 849.1 (894.0) -> 848.1 (894.0) MB, 0 ms > [Runtime::PerformGC]. > 7489050 ms: Mark-sweep 848.2 (894.0) -> 848.1 (894.0) MB, 484 ms (+ 1375 ms > in 70 steps since start of marking, biggest step 1140.266113 ms) [idle > notification: finalize incremental] [GC in old space requested]. > 7490932 ms: Mark-sweep 848.1 (894.0) -> 848.1 (894.0) MB, 491 ms (+ 1387 ms > in 70 steps since start of marking, biggest step 1148.691895 ms) [idle > notification: finalize incremental] [GC in old space requested]. > 7492810 ms: Mark-sweep 848.1 (894.0) -> 848.1 (894.0) MB, 488 ms (+ 1386 ms > in 70 steps since start of marking, biggest step 1149.963135 ms) [idle > notification: finalize incremental] [GC in old space requested]. > 7494681 ms: Mark-sweep 848.1 (894.0) -> 848.1 (894.0) MB, 482 ms (+ 1385 ms > in 70 steps since start of marking, biggest step 1150.884033 ms) [idle > notification: finalize incremental] [GC in old space requested]. > 7496534 ms: Mark-sweep 848.1 (894.0) -> 848.1 (894.0) MB, 479 ms (+ 1370 ms > in 70 steps since start of marking, biggest step 1136.897949 ms) [idle > notification: finalize incremental] [GC in old space requested]. > 7498415 ms: Mark-sweep 848.1 (894.0) -> 848.1 (894.0) MB, 485 ms (+ 1392 ms > in 70 steps since start of marking, biggest step 1153.990967 ms) [idle > notification: finalize incremental] [GC in old space requested]. > 7500279 ms: Mark-sweep 848.1 (894.0) -> 848.1 (894.0) MB, 473 ms (+ 1386 ms > in 70 steps since start of marking, biggest step 1149.422119 ms) [idle > notification: finalize incremental] [GC in old space requested]. > 7511092 ms: Scavenge 849.1 (894.0) -> 848.1 (894.0) MB, 0 ms > [Runtime::PerformGC]. > 7521936 ms: Scavenge 849.1 (894.0) -> 848.1 (894.0) MB, 0 ms > [Runtime::PerformGC]. > 7532793 ms: Scavenge 849.1 (894.0) -> 848.1 (894.0) MB, 0 ms > [Runtime::PerformGC]. > > In contrast with the default value version, there's no: > > 9464581 ms: Mark-sweep 848.1 (894.0) -> 848.0 (894.0) MB, 3521 ms [idle > notification: finalize idle rou > nd] [GC in old space requested]. > 9468118 ms: Mark-sweep 848.1 (894.0) -> 848.0 (894.0) MB, 3527 ms [idle > notification: finalize idle rou > nd] [GC in old space requested]. > > saved a lot of time. but [idle notification: finalize incremental] is still > a problem, and I've not find a simple way to change it. > > In summary: > 1. --nouse_idle_notification is useful, but is there any side effect? > 2. If there's not enough for program, node will not crash, but continuously > busy with GC. > 3. V8::IdleNotification(1) seems to be better for node, please any developer > pay attention to it. > > -- > Job Board: http://jobs.nodejs.org/ > Posting guidelines: > https://github.com/joyent/node/wiki/Mailing-List-Posting-Guidelines > You received this message because you are subscribed to the Google > Groups "nodejs" group. > To post to this group, send email to [email protected] > To unsubscribe from this group, send email to > [email protected] > For more options, visit this group at > http://groups.google.com/group/nodejs?hl=en?hl=en -- Job Board: http://jobs.nodejs.org/ Posting guidelines: https://github.com/joyent/node/wiki/Mailing-List-Posting-Guidelines You received this message because you are subscribed to the Google Groups "nodejs" group. To post to this group, send email to [email protected] To unsubscribe from this group, send email to [email protected] For more options, visit this group at http://groups.google.com/group/nodejs?hl=en?hl=en
