split the object to 4, but nothing changed. var obj_num = 5000000; var split = 4 var fill = []; for (var s = split; s > 0; s--) { fill[s]={}; for (var i = obj_num/split; i > 0; i--) { fill[s]["fill string*******************" + i] = "fill string" + i; }; } setInterval(function () { fill[0] = "something" + Date.now(); }, 1);
7697696 ms: Scavenge 850.4 (895.1) -> 849.4 (895.1) MB, 0 ms [Runtime::PerformGC]. 7700792 ms: Mark-sweep 849.5 (895.1) -> 849.4 (895.1) MB, 450 ms (+ 1630 ms in 9 steps since start of marking, biggest step 267.949951 ms) [idle notification: finalize incremental] [GC in old space requested]. 7702867 ms: Mark-sweep 849.4 (895.1) -> 849.4 (895.1) MB, 439 ms (+ 1633 ms in 9 steps since start of marking, biggest step 266.983887 ms) [idle notification: finalize incremental] [GC in old space requested]. 7704963 ms: Mark-sweep 849.4 (895.1) -> 849.4 (895.1) MB, 441 ms (+ 1639 ms in 9 steps since start of marking, biggest step 272.429932 ms) [idle notification: finalize incremental] [GC in old space requested]. 7707052 ms: Mark-sweep 849.4 (895.1) -> 849.4 (895.1) MB, 438 ms (+ 1639 ms in 9 steps since start of marking, biggest step 269.601074 ms) [idle notification: finalize incremental] [GC in old space requested]. 7709138 ms: Mark-sweep 849.4 (895.1) -> 849.4 (895.1) MB, 439 ms (+ 1635 ms in 9 steps since start of marking, biggest step 267.798828 ms) [idle notification: finalize incremental] [GC in old space requested]. 7712207 ms: Mark-sweep 849.4 (895.1) -> 849.4 (895.1) MB, 3059 ms [idle notification: finalize idle round] [GC in old space requested]. 7715267 ms: Mark-sweep 849.4 (895.1) -> 849.4 (895.1) MB, 3050 ms [idle notification: finalize idle round] [GC in old space requested]. 7726200 ms: Scavenge 850.4 (895.1) -> 849.4 (895.1) MB, 0 ms [Runtime::PerformGC]. 7737012 ms: Scavenge 850.4 (895.1) -> 849.4 (895.1) MB, 0 ms [Runtime::PerformGC]. 7747821 ms: Scavenge 850.4 (895.1) -> 849.4 (895.1) MB, 0 ms [Runtime::PerformGC]. 7758607 ms: Scavenge 850.4 (895.1) -> 849.4 (895.1) MB, 0 ms [Runtime::PerformGC]. 7769409 ms: Scavenge 850.4 (895.1) -> 849.4 (895.1) MB, 0 ms [Runtime::PerformGC]. 7772359 ms: Mark-sweep 849.5 (895.1) -> 849.4 (895.1) MB, 451 ms (+ 1639 ms in 9 steps since start of marking, biggest step 268.382812 ms) [idle notification: finalize incremental] [GC in old space requested]. 7774432 ms: Mark-sweep 849.4 (895.1) -> 849.4 (895.1) MB, 439 ms (+ 1631 ms in 9 steps since start of marking, biggest step 269.125000 ms) [idle notification: finalize incremental] [GC in old space requested]. 7776518 ms: Mark-sweep 849.4 (895.1) -> 849.4 (895.1) MB, 441 ms (+ 1633 ms in 9 steps since start of marking, biggest step 269.224854 ms) [idle notification: finalize incremental] [GC in old space requested]. 7778604 ms: Mark-sweep 849.4 (895.1) -> 849.4 (895.1) MB, 440 ms (+ 1635 ms in 9 steps since start of marking, biggest step 268.859131 ms) [idle notification: finalize incremental] [GC in old space requested]. 7780690 ms: Mark-sweep 849.4 (895.1) -> 849.4 (895.1) MB, 441 ms (+ 1633 ms in 9 steps since start of marking, biggest step 269.326904 ms) [idle notification: finalize incremental] [GC in old space requested]. 7783746 ms: Mark-sweep 849.4 (895.1) -> 849.4 (895.1) MB, 3046 ms [idle notification: finalize idle round] [GC in old space requested]. 7786807 ms: Mark-sweep 849.4 (895.1) -> 849.4 (895.1) MB, 3051 ms [idle notification: finalize idle round] [GC in old space requested]. 7797633 ms: Scavenge 850.4 (895.1) -> 849.4 (895.1) MB, 0 ms [Runtime::PerformGC]. On Wednesday, November 7, 2012 10:33:51 PM UTC+8, Vyacheslav Egorov wrote: > > 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 <free...@gmail.com <javascript:>> > 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 nod...@googlegroups.com<javascript:> > > To unsubscribe from this group, send email to > > nodejs+un...@googlegroups.com <javascript:> > > 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 nodejs@googlegroups.com To unsubscribe from this group, send email to nodejs+unsubscr...@googlegroups.com For more options, visit this group at http://groups.google.com/group/nodejs?hl=en?hl=en