I'm not focus on the initialization time, but GC impact in large memory
usage cases.
In the test case, I used 850MB memory, which is normal for a net server
application, the GC takes 5*450ms and 2*3050ms periodically(every tens of
seconds).
I think there should be some way to imporve it.
At least, users of node.js should be aware of this limitation.
On Friday, November 9, 2012 6:21:18 AM UTC+8, Vyacheslav Egorov wrote:
>
> Pauses that follow initialization will actually become much smaller
> (given that you disable idle notification that are abused by node).
>
> Pauses during initialization of your test are irrelevant because your
> allocation rate is not at the realistic level.
>
> It is highly unlikely that your application does nothing but allocates
> hundreds of megabytes per each request.
>
>
> Vyacheslav Egorov
>
>
> On Thu, Nov 8, 2012 at 12:45 AM, darcy <free...@gmail.com <javascript:>>
> wrote:
> > 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> 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
> >> > To unsubscribe from this group, send email to
> >> > nodejs+un...@googlegroups.com
> >> > 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 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
