RSS memory leak on highload

baryshev commented 12 years ago

RSS memory doesn't release after doing some intensive tasks (highload).

My environment

CPU: Core i5 450M 2.4Ghz
OS: Ubuntu Server 12.04 (64 bit)
RAM: 4096Mb
Node.JS verison: 0.8.14
How to reproduce leak
1. Download test case.
2. Start node server.js.
3. Start node client.js.
4. Wait until RSS memory usage of node server.js rise up to 250-300Mb (or more).
5. Stop client.js and wait some time to give server.js time to complete all tasks.
6. If heap memory hasn't released you may start client.js for a short time again, to get GC of server.js work.
  Expected result

RSS memory will be released as well as a heap memory and will be comparable with initial values.

Actual result

Heap memory released successfully, but RSS memory not.

My results:

Before test:

{ rss: 9768960, heapTotal: 6131200, heapUsed: 2604752 }

After test:

{ rss: 184217600, heapTotal: 6114560, heapUsed: 2660472 }

Related discussions

superfeedr commented 12 years ago

I believe we're seeing the same error. Thanks @baryshev for your thorough testing and debugging!

bnoordhuis commented 12 years ago

I see no memory leaks with your example. You are however buffering up a lot of data, which explains the growing RSS.

I've said it before and I'll say it again: RSS is an extremely poor metric for determining memory leaks. malloc implementations are very reluctant to return memory to the system even under ideal circumstances (i.e. no heap fragmentation). Here is a gist that demonstrates that.

superfeedr commented 12 years ago

@bnoordhuis Do you know of any tool/technique to see what are these buffers that are being allocated and how we can hopefully reduce their amount?

bnoordhuis commented 12 years ago

@superfeedr You can use something node-inspector or node-heapdump to create and inspect heap snapshots.

Regarding the test case (which I'll post here for the sake of posterity):

var server = net.createServer(function (socket) {
  socket.on('data', function() {
    setTimeout(function() {
      for (var i = 0; i < 100000; i++) {
        var d = new Date();
        socket.write(d.toString());
      }
    }, 10);
  });
});

It writes data to the socket without checking the return value of write(). The core logic should be rewritten to something like this:

var i = 1e5;
function f() {
  for (; i > 0; --i)
    if (socket.write(d.toString()) === false) // the strict check is not optional
      return socket.on('drain', f);
}
f();

superfeedr commented 12 years ago

@bnoordhuis But wait, I thought Buffers were outside of the heap? I understand RSS is not the right metric to check for leaks, but our heap just stays reasonnably small (at most 100MB), while RSS explodes (can go easily to 1GB). We want to know what's in there, because this growing RSS (whether it's a leak or not) causes trouble and forces the machine to start swapping.

bnoordhuis commented 12 years ago

But wait, I thought Buffers were outside of the heap?

Yes, but as of commit 6a128e0 (v0.8.12 and up) they're reported properly in heap snapshots.

superfeedr commented 12 years ago

Brilliant! Back to exploration. Thanks for the precious help. I expect though that they're not part of process.memoryUsage()'s heapTotal?

bnoordhuis commented 12 years ago

I expect though that they're not part of process.memoryUsage()'s heapTotal?

Indeed, but you can find out their total size with the statistics extension:

$ node --track_gc_object_stats -p 'Buffer(10*1024*1024); getV8Statistics()'
{ total_committed_bytes: 35635200,
  new_space_live_bytes: 391880,
  new_space_available_bytes: 656464,
  new_space_commited_bytes: 1048576,
  old_pointer_space_live_bytes: 524288,
  old_pointer_space_available_bytes: 0,
  old_pointer_space_commited_bytes: 524288,
  old_data_space_live_bytes: 196608,
  old_data_space_available_bytes: 0,
  old_data_space_commited_bytes: 196608,
  code_space_live_bytes: 1019904,
  code_space_available_bytes: 0,
  code_space_commited_bytes: 1019904,
  cell_space_live_bytes: 98304,
  cell_space_available_bytes: 0,
  cell_space_commited_bytes: 98304,
  lo_space_live_bytes: 0,
  lo_space_available_bytes: 1498414848,
  lo_space_commited_bytes: 0,
  amount_of_external_allocated_memory: 10485816 } # <- this

spollack commented 11 years ago

@bnoordhuis how do i get access to that extension? I tried the command line above, and node tells me it doesn't recognize this flag --track_gc_object_stats. I tried this on 0.8.18 and 0.8.14. Thanks!

node --track_gc_object_stats -p -e 'Buffer(10_1024_1024); getV8Statistics();' Error: unrecognized flag --track_gc_object_stats Try --help for options

Buffer(10_1024_1024); getV8Statistics(); ^ ReferenceError: getV8Statistics is not defined at eval:1:23 at Object. (eval-wrapper:6:22) at Module._compile (module.js:449:26) at evalScript (node.js:282:25) at startup (node.js:76:7) at node.js:627:3

bnoordhuis commented 11 years ago

@spollack It's only available in the master branch, the V8 version in v0.8 is too old.

bobrik commented 11 years ago

@bnoordhuis my rss is increasing, but amount_of_external_allocated_memory stays low:

Before gc():

{"rss":265080832,"heapTotal":56172032,"heapUsed":8697768}
{
    "total_committed_bytes": 57688064,
    "new_space_live_bytes": 4027464,
    "new_space_available_bytes": 12749592,
    "new_space_commited_bytes": 33554432,
    "old_pointer_space_live_bytes": 2159320,
    "old_pointer_space_available_bytes": 12812072,
    "old_pointer_space_commited_bytes": 14971392,
    "old_data_space_live_bytes": 1095272,
    "old_data_space_available_bytes": 1165208,
    "old_data_space_commited_bytes": 2260480,
    "code_space_live_bytes": 1219904,
    "code_space_available_bytes": 1839808,
    "code_space_commited_bytes": 3059712,
    "cell_space_live_bytes": 31120,
    "cell_space_available_bytes": 99952,
    "cell_space_commited_bytes": 131072,
    "lo_space_live_bytes": 0,
    "lo_space_available_bytes": 1476361984,
    "lo_space_commited_bytes": 0,
    "amount_of_external_allocated_memory": 1081624
}

After gc():

{"rss":258056192,"heapTotal":49980416,"heapUsed":4513704}
{
    "total_committed_bytes": 51396608,
    "new_space_live_bytes": 2080,
    "new_space_available_bytes": 16774976,
    "new_space_commited_bytes": 33554432,
    "old_pointer_space_live_bytes": 2127400,
    "old_pointer_space_available_bytes": 6652376,
    "old_pointer_space_commited_bytes": 8779776,
    "old_data_space_live_bytes": 1802640,
    "old_data_space_available_bytes": 457840,
    "old_data_space_commited_bytes": 2260480,
    "code_space_live_bytes": 1145440,
    "code_space_available_bytes": 1914272,
    "code_space_commited_bytes": 3059712,
    "cell_space_live_bytes": 30304,
    "cell_space_available_bytes": 100768,
    "cell_space_commited_bytes": 131072,
    "lo_space_live_bytes": 0,
    "lo_space_available_bytes": 1482653440,
    "lo_space_commited_bytes": 0,
    "amount_of_external_allocated_memory": 1065128
}

heap dump file is around 250mb, but chrome says that it is only 5.1mb. What am I missing? My app processes around 20m simple requests per day and becomes less responsible (3ms on the first day -> up to 500ms on the third day). I don't use compiled modules, only redis and empty-gif.

node.js 0.10.10

trevnorris commented 11 years ago

@bobrik dead thread probably won't get you many responses. i'd say throw this on the mailing list. and some code is going to much more helpful.

ApsOps commented 8 years ago

@superfeedr Hi. It's pretty late, but were you able to figure out the reason? I'm facing this behavior in one of my apps as well:

I understand RSS is not the right metric to check for leaks, but our heap just stays reasonnably small (at most 100MB), while RSS explodes (can go easily to 1GB). We want to know what's in there, because this growing RSS (whether it's a leak or not) causes trouble and forces the machine to start swapping.

nodejs / node-v0.x-archive