Excessive garbage collection
psubocz
I was very excited about node.js when I heard about it for the first
time. So I rewrote a simple web service we are using, from c++ do
javascript and made some tests - benchmarks and production.
Everything went really smooth and I was amazed with simplicity of
code, and performance, but...
But the garbage collector is a deal-breaker.
The case: load some data into a map, on each request grab some data,
pack it in json'ish format nad send to the client. After loading the
data node.js takes about 150MB of memory, which is great - just like
the c++ version.
When I launch the service in the test or production environment with --
trace_gc I've got very similar patterns:
Scavenge 107.7 -> 106.8 MB, 1 ms.
Scavenge 107.8 -> 106.8 MB, 0 ms.
Scavenge 107.8 -> 106.8 MB, 1 ms.
Scavenge 107.0 -> 106.8 MB, 1 ms.
Mark-sweep 106.8 -> 106.6 MB, 1 / 502 ms.
Mark-compact 107.1 -> 106.6 MB, 1054 ms.
So, form time to time it is stopping all execution for more than 1.5s
(!)
Moreover the longer node is running, the often mark-sweep/mark-compact
is performed. And the time taken is always unacceptable.
Here is some very simple code showing this behaviour:
var data = [];
for(var i=0; i<5000000; i++) {
data.push({a:1, b:2, c:3, d:4});
}
function test() {
var d = [];
for(var i=0; i<100; i++) {
d.push(data[Math.floor(Math.random()*data.length)]);
}
}
setInterval(test, 1);
Is there any way to change garbage collector's behaviour to perform
better in similar cases? Maybe to use more memory, and launch less
often. Or to split the process in smaller chunks. What ever.
I was thinking about storing the data in some kind of c++ module (gdbm
handler of something like that), but this sounds like a hack, not a
solution.
Do you have any ideas or similar observations?
Best regards
Pawel Subocz
billywhizz
in v8 to me. It's even worse if i force garbage collections using
http://github.com/billywhizz/node-gc. seems to whack the cpu and take
lots of time every time GC collection happens after it reaches a
certain threshold. changing the timeout for the test function makes no
difference either.
also, it's never actually finding any memory to free up as far as i
can see...
this is my output:
Scavenge 2.1 -> 2.0 MB, 0 ms.
Scavenge 2.7 -> 2.6 MB, 1 ms.
Mark-sweep 3.4 -> 3.2 MB, 3 ms.
Scavenge 5.2 -> 4.9 MB, 3 ms.
Scavenge 7.0 -> 6.6 MB, 2 ms.
Mark-sweep 11.8 -> 10.1 MB, 13 ms.
Scavenge 16.1 -> 16.1 MB, 8 ms.
Mark-sweep 25.1 -> 21.8 MB, 31 ms.
Scavenge 30.7 -> 30.7 MB, 16 ms.
Scavenge 49.4 -> 49.4 MB, 36 ms.
Scavenge 61.4 -> 61.4 MB, 30 ms.
Mark-sweep 62.2 -> 54.8 MB, 67 ms.
Scavenge 80.8 -> 80.8 MB, 29 ms.
Scavenge 107.7 -> 107.7 MB, 35 ms.
Scavenge 119.7 -> 119.7 MB, 34 ms.
Scavenge 131.7 -> 131.7 MB, 31 ms.
Mark-sweep 166.1 -> 134.6 MB, 161 ms.
Scavenge 150.6 -> 150.6 MB, 33 ms.
Scavenge 162.6 -> 162.6 MB, 34 ms.
Scavenge 174.6 -> 174.6 MB, 33 ms.
Scavenge 220.2 -> 220.2 MB, 43 ms.
Scavenge 232.2 -> 232.2 MB, 42 ms.
Scavenge 244.2 -> 244.2 MB, 36 ms.
Scavenge 256.2 -> 256.2 MB, 36 ms.
Scavenge 268.2 -> 268.2 MB, 36 ms.
Scavenge 280.2 -> 280.2 MB, 37 ms.
Scavenge 292.2 -> 292.2 MB, 37 ms.
Scavenge 354.6 -> 354.6 MB, 51 ms.
Scavenge 366.6 -> 366.6 MB, 49 ms.
Mark-sweep 378.6 -> 319.1 MB, 363 ms.
Scavenge 335.1 -> 319.1 MB, 3 ms.
Scavenge 324.3 -> 319.1 MB, 3 ms.
Mark-sweep 319.1 -> 319.1 MB, 336 ms.
Mark-compact 319.1 -> 319.1 MB, 793 ms.
Scavenge 320.1 -> 319.1 MB, 3 ms.
Scavenge 320.1 -> 319.1 MB, 3 ms.
Scavenge 320.1 -> 319.1 MB, 3 ms.
Scavenge 320.1 -> 319.1 MB, 3 ms.
Scavenge 320.1 -> 319.1 MB, 3 ms.
Scavenge 320.1 -> 319.1 MB, 3 ms.
Scavenge 320.1 -> 319.1 MB, 3 ms.
Scavenge 320.1 -> 319.1 MB, 3 ms.
Scavenge 320.1 -> 319.1 MB, 3 ms.
Scavenge 320.1 -> 319.1 MB, 3 ms.
Scavenge 320.1 -> 319.1 MB, 3 ms.
Scavenge 320.1 -> 319.1 MB, 3 ms.
Scavenge 320.1 -> 319.1 MB, 3 ms.
Scavenge 320.1 -> 319.1 MB, 3 ms.
Scavenge 320.1 -> 319.1 MB, 3 ms.
Scavenge 320.1 -> 319.1 MB, 3 ms.
Scavenge 320.1 -> 319.1 MB, 3 ms.
Scavenge 320.1 -> 319.1 MB, 3 ms.
Scavenge 320.1 -> 319.1 MB, 3 ms.
Scavenge 320.1 -> 319.1 MB, 3 ms.
Scavenge 320.1 -> 319.1 MB, 3 ms.
Scavenge 320.1 -> 319.1 MB, 3 ms.
Scavenge 320.1 -> 319.1 MB, 3 ms.
Scavenge 320.1 -> 319.1 MB, 3 ms.
Scavenge 319.6 -> 319.1 MB, 3 ms.
Mark-sweep 319.1 -> 319.1 MB, 335 ms.
Mark-compact 319.1 -> 319.1 MB, 790 ms.
Scavenge 320.1 -> 319.1 MB, 3 ms.
Scavenge 320.1 -> 319.1 MB, 3 ms.
Scavenge 320.1 -> 319.1 MB, 3 ms.
Scavenge 320.1 -> 319.1 MB, 3 ms.
Scavenge 320.1 -> 319.1 MB, 3 ms.
Scavenge 320.1 -> 319.1 MB, 3 ms.
Jonas Pfenniger (zimbatm)
Depending on the nature of the datas, I would first try to pack them into Buffer objects, with a free list like the http module does with the parsers. If concatenating lots of strings also look for using array.join() to limit allocations.
sent from my phone
> --
> 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.
>
r...@tinyclouds.org
Pawal,
I wonder if you've seen a difference in the master branch rather than
v0.2 branch?
billywhizz
items is very large (> 1m), even if i split the data across multiple
smaller arrays, it still does long pauses...
Scavenge 256.2 -> 256.2 MB, 39 ms.
Scavenge 268.2 -> 268.2 MB, 39 ms.
Scavenge 280.2 -> 280.2 MB, 39 ms.
Scavenge 292.2 -> 292.2 MB, 39 ms.
Scavenge 354.6 -> 354.6 MB, 49 ms.
Scavenge 366.6 -> 366.6 MB, 48 ms.
Mark-sweep 378.6 -> 319.2 MB, 304 ms.
Scavenge 335.2 -> 319.2 MB, 3 ms.
Scavenge 324.7 -> 319.2 MB, 3 ms.
Mark-sweep 319.2 -> 319.2 MB, 273 ms.
Mark-compact 319.2 -> 319.2 MB, 746 ms.
Scavenge 320.2 -> 319.2 MB, 3 ms.
Scavenge 320.2 -> 319.2 MB, 3 ms.
Scavenge 320.2 -> 319.2 MB, 3 ms.
Scavenge 320.2 -> 319.2 MB, 3 ms.
Scavenge 320.2 -> 319.2 MB, 3 ms.
Scavenge 320.2 -> 319.2 MB, 3 ms.
Scavenge 320.2 -> 319.2 MB, 3 ms.
Scavenge 320.2 -> 319.2 MB, 3 ms.
Scavenge 320.2 -> 319.2 MB, 3 ms.
Scavenge 320.2 -> 319.2 MB, 3 ms.
Scavenge 320.2 -> 319.2 MB, 3 ms.
Scavenge 320.2 -> 319.2 MB, 3 ms.
Scavenge 320.2 -> 319.2 MB, 3 ms.
Scavenge 320.2 -> 319.2 MB, 3 ms.
Scavenge 320.2 -> 319.2 MB, 3 ms.
Scavenge 320.2 -> 319.2 MB, 3 ms.
Scavenge 320.2 -> 319.2 MB, 3 ms.
Scavenge 320.2 -> 319.2 MB, 3 ms.
Scavenge 320.2 -> 319.2 MB, 3 ms.
Scavenge 320.2 -> 319.2 MB, 3 ms.
Scavenge 320.2 -> 319.2 MB, 3 ms.
Scavenge 320.2 -> 319.2 MB, 3 ms.
Scavenge 320.2 -> 319.2 MB, 3 ms.
Scavenge 320.2 -> 319.2 MB, 3 ms.
Scavenge 319.9 -> 319.2 MB, 3 ms.
Mark-sweep 319.2 -> 319.2 MB, 273 ms.
Mark-compact 319.2 -> 319.2 MB, 738 ms.
Scavenge 320.2 -> 319.2 MB, 3 ms.
Scavenge 320.2 -> 319.2 MB, 3 ms.
On Oct 11, 7:33 pm, r...@tinyclouds.org wrote:
Mariusz Nowak
I have script (I work on OSX) in which I load many (ca 40) large (ca
0.25GB each) files into buffers.
They're loaded and processed one after another, no references are
kept.. anyway memory usage grows as script runs.
What's more interesting when script exits (normally) it leaves kernel
process taking a lot space in memory (it's not node process which I
could just kill). Even more interesting is: memory becomes freed only
if I restart system or remove (permanently) files that were loaded
into buffers when script was running :)
I have no idea how can I work around that and it's pretty frustrating
as my system becomes slow.
Mariusz Nowak
Renato Elias
fs.stat('/tmp/world', function (err, stats) {
if (err) throw err;
console.log('stats: ' + JSON.stringify(stats)); console.log(x);});fs.stat('/tmp/world', function(x, undefined){return function (err, stats) {
if (err) throw err;
console.log('stats: ' + JSON.stringify(stats)); console.log(x);};Felix Geisendörfer
I have a similar script that also keeps eating memory. It seems like
there are some general problems with buffer GC, see:
http://groups.google.com/group/nodejs-dev/browse_thread/thread/90d3113394df4b65/3891895422fb61f9
However, I don't have any problems with the memory being freed up
after I kill the process. Maybe that is system specific? I'm on OSX
10.6.4
--fg
Vyacheslav Egorov
> Mark-compact 107.1 -> 106.6 MB, 1054 ms.
I think these GCs are triggered by V8::IdleNotifications which is
invoked by node.js itself. The whole idea behind IdleNotification is
that it should be called when pause does not actually matter [i.e. it
would not be noticed by user]
But I also see a low hanging fruit here: V8 could at least "cancel"
compaction when it saw that almost all objects in heap are alive.
--
Vyacheslav Egorov
Mariusz Nowak
Thanks for that point. Yeah it runs with recursion, so indeed the
issue of memory usage growing was because contexts are kept (my bad).
Anyway it's still weird it persists after script finished it's
execution. I guess it might be related to problem cited by Felix
r...@tinyclouds.org
>> Mark-sweep 106.8 -> 106.6 MB, 1 / 502 ms.
>> Mark-compact 107.1 -> 106.6 MB, 1054 ms.
>
> I think these GCs are triggered by V8::IdleNotifications which is
> invoked by node.js itself. The whole idea behind IdleNotification is
> that it should be called when pause does not actually matter [i.e. it
> would not be noticed by user]
Yes, we can probably be smarter about when we call it. Current logic is:
- Every 5 seconds run a timer which decides:
- If the last 5 iterations happened in less than 0.7 seconds
- Call V8::IdleNotification over and over until it returns true or
something happens on the event loop.
> But I also see a low hanging fruit here: V8 could at least "cancel"
> compaction when it saw that almost all objects in heap are alive.
Sounds good!
Erik Corry
> I have similar problem, however not sure if directly related.
>
> I have script (I work on OSX) in which I load many (ca 40) large (ca
> 0.25GB each) files into buffers.
> They're loaded and processed one after another, no references are
> kept.. anyway memory usage grows as script runs.
> What's more interesting when script exits (normally) it leaves kernel
> process taking a lot space in memory (it's not node process which I
> could just kill). Even more interesting is: memory becomes freed only
This doesn't sound like an issue with V8. If the V8/node process has
been killed then the memory should be gone.
I'm not quite sure what a kernel process is. Normally on Unix there a
process can be in kernel mode or user mode, but it's the same process.
Kernel process sounds like something the kernel would use to
implement asynchronous IO. So it sounds a bit like a bug in node's
AIO libraries or MacOSX's implementation of AIO.
Renato Elias
I processed some gigabytes and I did not have this problem
Felix Geisendörfer
test that shows a buffer 40 MB buffer that doesn't get GC'ed.
http://github.com/felixge/node/commit/0aac07e09374daebc6fd4fed8837c29d0c8c44c8
--fg
On Oct 13, 3:25 pm, Renato Elias <renato.el...@gmail.com> wrote:
> I you have script for test ?
>
> I processed some gigabytes and I did not have this problem
>
> On Oct 13, 2010, at 8:52 AM, Erik Corry wrote:
>
>
>
Felix Geisendörfer
option which gives you access to a global gc() function:
https://gist.github.com/06c6088be4323fec2d92
What is really interesting here is that if I leave out the for loop
that fills the buffer with random bytes, the GC seems to work. If I
only set half of the bytes of the buffer, the other half is collected.
--fg
On Oct 13, 3:36 pm, Felix Geisendörfer <fe...@debuggable.com> wrote:
> > I you have script for test ?
>
> test that shows a buffer 40 MB buffer that doesn't get GC'ed.
>
Ben Noordhuis
> https://gist.github.com/06c6088be4323fec2d92
RSS is probably not a good indicator for this, the OS won't shrink it
(swap, reclaim) if there is no memory pressure.
Vyacheslav Egorov
What OS your are using?
On Mac OS X I see the following:
whitestar:node mraleph$ ./node --expose-gc --trace-gc ./test.js
Scavenge 1.0 -> 1.0 MB, 0 ms.
Mark-sweep 1.4 -> 1.3 MB, 5 / 7 ms.
whitestar:node mraleph$
notice that 5 ms were spent inside external scope --- most probably it
was deallocation of buffer's underlying storage.
Another point you should take into account: node uses new/delete
operators to manage buffer's underlying storage. This creates an
additional layer of abstraction between OS and node. C++ runtime can
manage it's memory in different ways: e.g. it can decide not to return
memory region occupied by deleted object with intent to reuse it for
later allocations.
--
Vyacheslav Egorov
On Wed, Oct 13, 2010 at 3:49 PM, Felix Geisendörfer
Felix Geisendörfer
----------------------------------------------------
node --expose_gc --trace_gc test/simple/test-buffer-memory-leak.js
Mark-sweep 2.0 -> 1.8 MB, 8 / 11 ms.
node.js:50
throw e; // process.nextTick error, or 'error' event on first tick
^
Error: 40 MB Buffer was not collected. 40.71 MB still in use.
----------------------------------------------------
> RSS is probably not a good indicator for this, the > OS won't shrink it
> (swap, reclaim) if there is no memory pressure.
600 MB of memory usage after uploading a bunch of files to a server
and I don't like it.
Do you have a better idea to trace down the cause of that? How can I
force the operating system to apply "memory pressure"?
--fg
Vyacheslav Egorov
Interesting. Try applying the following patch and post output (it also
fixes a small glitch in node sources. delete[] should be used to free
something allocated by new[]).
> Do you have a better idea to trace down the cause of that? How can I
> force the operating system to apply "memory pressure"?
I am pretty sure this has nothing to do with memory pressure. If C++
runtime decided not to return memory to OS you probably cannot force
it.
--
Vyacheslav Egorov
Felix Geisendörfer
--------------------------------------------------
node --expose_gc --trace_gc test/simple/test-buffer-memory-leak.js
new buffer 0x10102d000 [8192]
new buffer 0x101047e00 [8192]
new buffer 0x101027400 [8192]
new buffer 0x125800000 [41943040]
free buffer 0x125800000
free buffer 0x101047e00
free buffer 0x10102d000
node.js:50
throw e; // process.nextTick error, or 'error' event on first tick
^
Error: 40 MB Buffer was not collected. 40.71 MB still in use.
--------------------------------------------------
gets to it, but the OS/C++ runtime don't let go of it.
Is that correct?
--fg
> < 1KViewDownload
Ben Noordhuis
> I am pretty sure this has nothing to do with memory pressure.
But it does. Felix's test measures RSS, the part of the program that
is in physical memory. If there is no memory pressure[1], no other
processes requesting (and using) memory, the OS will neither reclaim
nor swap so the RSS won't shrink.
> If C++ runtime decided not to return memory to OS you probably cannot force it.
Partially true. The runtime may not return the memory (I think glibc
indeed does not but don't quote me on this) but that doesn't mean the
OS won't swap out unused pages.
@Felix: there is no silver bullet for debugging memory usage. Your
best bet is valgrind + node_g.
[1] That should actually read 'VM pressure' but VM is an overloaded
concept on this mailing list so let's go with memory pressure.
Vyacheslav Egorov
<fe...@debuggable.com> wrote:
> If I'm reading this correctly the buffer gets freed even before the GC
> gets to it
It is freed when GC gets to it (gc trace line is printed at the very
end of GC).
> , but the OS/C++ runtime don't let go of it.
It looks so.
> But it does. Felix's test measures RSS, the part of the program that
> is in physical memory.
I stand corrected. I was talking more about general case than about
this particular approach to leak detection.
--
Vyacheslav Egorov