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 <freeda...@gmail.com> 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 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
--
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
