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
