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
