VM: Extreme memory growth

It looks like context objects are not collected by the GC until the max memory limit is reached.

'use strict';

var vm = require('vm');

var script = vm.createScript();
var context = vm.createContext();

for (var i = 0; i < 10000000; i++) {
  vm.runInNewContext('(_$_v.length-1)', {
    '_$_v': [
      { category: 'reference',
        author: 'Nigel Rees',
        title: 'Sayings of the Century',
        price: 8.95 },
      { category: 'fiction',
        author: 'Evelyn Waugh',
        title: 'Sword of Honour',
        price: 12.99 },
      { category: 'fiction',
        author: 'Herman Melville',
        title: 'Moby Dick',
        isbn: '0-553-21311-3',
        price: 8.99 },
      { category: 'fiction',
        author: 'J. R. R. Tolkien',
        title: 'The Lord of the Rings',
        isbn: '0-395-19395-8',
        price: 22.99 }
    ]
  });

  if (i % 10 === 0) {
    console.log("After", i, "iterations:", parseInt(process.memoryUsage().heapTotal / 1024 / 1024), "MB");
  }
}

$ node test.js
After 0 iterations: 9 MB
After 10 iterations: 20 MB
After 20 iterations: 30 MB
After 30 iterations: 46 MB
After 40 iterations: 52 MB
After 50 iterations: 60 MB
After 60 iterations: 69 MB
After 70 iterations: 95 MB
After 80 iterations: 101 MB
After 90 iterations: 107 MB
After 100 iterations: 114 MB
After 110 iterations: 120 MB
After 120 iterations: 126 MB
After 130 iterations: 137 MB
After 140 iterations: 142 MB
After 150 iterations: 154 MB
After 160 iterations: 159 MB
After 170 iterations: 166 MB
After 180 iterations: 178 MB
After 190 iterations: 184 MB
After 200 iterations: 191 MB
After 210 iterations: 203 MB
After 220 iterations: 208 MB
After 230 iterations: 221 MB
After 240 iterations: 227 MB
After 250 iterations: 234 MB
After 260 iterations: 245 MB
After 270 iterations: 253 MB
After 280 iterations: 265 MB
After 290 iterations: 270 MB
After 300 iterations: 277 MB
After 310 iterations: 288 MB
After 320 iterations: 296 MB
After 330 iterations: 302 MB
After 340 iterations: 313 MB
After 350 iterations: 320 MB
After 360 iterations: 333 MB
After 370 iterations: 339 MB
After 380 iterations: 346 MB
After 390 iterations: 357 MB
After 400 iterations: 363 MB
After 410 iterations: 365 MB
After 420 iterations: 365 MB
After 430 iterations: 365 MB
After 440 iterations: 365 MB
After 450 iterations: 365 MB
After 460 iterations: 367 MB
After 470 iterations: 370 MB
After 480 iterations: 376 MB
After 490 iterations: 385 MB
After 500 iterations: 392 MB

If I specify --max-old-space-size I can stop the memory growth.

 node --max-old-space-size=32 test2.js
After 0 iterations: 9 MB
After 10 iterations: 20 MB
After 20 iterations: 39 MB
After 30 iterations: 44 MB
After 40 iterations: 10 MB
After 50 iterations: 20 MB
After 60 iterations: 30 MB
After 70 iterations: 47 MB
After 80 iterations: 17 MB
After 90 iterations: 25 MB
After 100 iterations: 31 MB
After 110 iterations: 47 MB
After 120 iterations: 15 MB
After 130 iterations: 26 MB

If I rewrite the code to reuse the context object, memory usage and performance are a lot better:

'use strict';

var vm = require('vm');

var script = vm.createScript('(_$_v.length-1)');
var context = vm.createContext();

for (var i = 0; i < 10000000; i++) {
  context['_$_v'] = [
    { category: 'reference',
      author: 'Nigel Rees',
      title: 'Sayings of the Century',
      price: 8.95 },
    { category: 'fiction',
      author: 'Evelyn Waugh',
      title: 'Sword of Honour',
      price: 12.99 },
    { category: 'fiction',
      author: 'Herman Melville',
      title: 'Moby Dick',
      isbn: '0-553-21311-3',
      price: 8.99 },
    { category: 'fiction',
      author: 'J. R. R. Tolkien',
      title: 'The Lord of the Rings',
      isbn: '0-395-19395-8',
      price: 22.99 }
  ];

  script.runInContext(context);

  if (i % 10000 === 0) {
    console.log("After", i, "iterations:", parseInt(process.memoryUsage().heapTotal / 1024 / 1024), "MB");
  }
}

$ node test.js
After 0 iterations: 9 MB
After 10000 iterations: 11 MB
After 20000 iterations: 11 MB
After 30000 iterations: 12 MB
After 40000 iterations: 13 MB
After 50000 iterations: 13 MB
After 60000 iterations: 13 MB
After 70000 iterations: 13 MB
After 80000 iterations: 13 MB
After 90000 iterations: 13 MB
After 100000 iterations: 13 MB
After 110000 iterations: 14 MB
After 120000 iterations: 14 MB
After 130000 iterations: 15 MB
After 140000 iterations: 16 MB
After 150000 iterations: 17 MB
After 160000 iterations: 17 MB
After 170000 iterations: 18 MB
After 180000 iterations: 19 MB
After 190000 iterations: 20 MB
After 200000 iterations: 20 MB
After 210000 iterations: 21 MB
After 220000 iterations: 22 MB
After 230000 iterations: 22 MB
After 240000 iterations: 23 MB
After 250000 iterations: 23 MB
After 260000 iterations: 23 MB
After 270000 iterations: 23 MB
After 280000 iterations: 23 MB
After 290000 iterations: 23 MB
After 300000 iterations: 23 MB
After 310000 iterations: 23 MB
After 320000 iterations: 23 MB
After 330000 iterations: 23 MB
After 340000 iterations: 23 MB
After 350000 iterations: 23 MB
After 360000 iterations: 23 MB
After 370000 iterations: 23 MB
After 380000 iterations: 19 MB
After 390000 iterations: 19 MB
After 400000 iterations: 19 MB
After 410000 iterations: 19 MB
After 420000 iterations: 19 MB
After 430000 iterations: 19 MB
After 440000 iterations: 19 MB
After 450000 iterations: 19 MB
After 460000 iterations: 19 MB
After 470000 iterations: 19 MB
After 480000 iterations: 19 MB
After 490000 iterations: 19 MB
After 500000 iterations: 19 MB
After 510000 iterations: 20 MB
After 520000 iterations: 20 MB
After 530000 iterations: 21 MB
After 540000 iterations: 22 MB

I understand why performance is a lot better (re-using the same object is obviously faster than creating new ones), but why is the memory profile so different?

The fact that the memory growth is stopped by using --max-old-space-size means that those objects are collectable by gc. Probably gc isn't triggered in this situation. Will take a look in an hour.

What you're seeing is more or less the expected behavior. Garbage collection is expensive and garbage collecting VM contexts even more so, so V8 will generally prefer to grow the heap instead of sweeping it.

If you start node with --expose_gc and call gc() every n iterations, memory usage should be much more stable.

@bnoordhuis

@bnoordhuis This is still quite unexpected, especially as we didn't have this problem with v0.10. I understand that the internals of the vm module changed quite a bit, but it still feels that something is quite off if memory usage suddenly grows to +1GB where it was pretty stable at around 150MB before.

I understand that I could either expose the gc or limit the max heap size, but both solutions feel like some sort of hack to me.

It is what it is. There is not much we (node.js) can do here, GC heuristics are predominantly a V8 affair. We can't really hint at V8 either that now would be a good time to collect garbage because node.js doesn't really know when the VM context is well and truly dead.

Oh well, that's unfortunate. :( I worked around this issue for now by re-using the same context instead of recreating a new context. Not perfect, but better than using up all available memory on the system.

The code fires only scavenges, but not mark-sweeps (until the total RSS reaches the limit).
The memory is reclaimed by mark-sweeps, scavenges are ineffective here.

It's also worth noting that somewhy --expose-gc (without calling gc() manually) makes the situation worse when --max-old-space-size is specified.

node --max-old-space-size=32 test.js — works (checked up to 1000 iteration).
node --max-old-space-size=32 --expose-gc test.js — crashes after about 30-40 iterations.
node --max-old-space-size=100 --expose-gc test.js — crashes after about 140 iterations.
node --max-old-space-size=200 --expose-gc test.js — crashes after about 280 iterations.

test.js is exactly the same in all four cases.

@ChALkeR

@ChALkeR What I've seen in our app is that even when after running for more than 48 hours, none of the memory that is used up by the contexts is ever really freed again. Basically, memory usage grows to some limit around 1GB and then stays there forever. Not sure why no mark-sweep is triggered and why these context objects are not cleaned up.

none of the memory that is used up by the contexts is ever really freed again. Basically, memory usage grows to some limit around 1GB and then stays there forever.

What do you mean by «not freed again»? It's actually freed when a mark-sweep is triggered and re-used for further allocations. If your heapUsed stays constant for a lot of operations generally means that GC is triggered too often, frees too little space, and that the freed space is immediately consumed. That sutuation is suboptimal, it usually means big gc pauses and lags as a result.

If your RSS does not go down when something is freed — that's normal even for plain c/c++ programs.

A side note: vm.runInNewContext(…) is not required here, the problem could be reproduced with just vm.createContext(); calls.

@indutny

@indutny Maybe ContextifyContext constructor and destructor should call AdjustAmountOfExternalAllocatedMemory?

That's about 1 MiB per each (empty) ContextifyContext for me.

@ChALkeR

@ChALkeR One thing I noticed:

The contextify module used NanContextDisposedNotification https://github.com/brianmcd/contextify/blob/1ed0631b435f6301986cc0890c36a29d5c55de97/src/contextify.cc#L31

Provide a GC hint that the context has gone away. Without this call it does not seem that the collector will touch the context until under extreme stress.

I don't see any call to ContextDisposedNotification in the node_contextify.cc. Might this be related?

These back-port to v4.x with a rather simple merge conflict resolution. I have verified that problem gets fixed in v4.x after the backport.

@nodejs/lts: what would be the process to get this backported? These 4 commits (ebbbc5a...66566df) need to be backported, but I don't want to tag the issue (#5392) with lts-watch tag.

For some reason I thought that the issue contained more commits than just these 4. That is not the case, so I am just going to tag the issue.

I have test builds showing up here: https://nodejs.org/download/test/v4.3.2-test20160316bdc07626e8/ using https://github.com/rvagg/io.js/tree/5392-backport where I have those 4 commits applied on top of the current v4.x. I'd appreciate it if those having trouble with this problem could test it out and report back.

@rvagg

It turns out the above 4 commits are not functionally complete – an additional commit (#5800) is needed to avoid a crash. (@rvagg, would you mind putting together another build?)

I would really like to get some independent verification whether this memory growth issue is indeed fixed. In my experimentation, the reduced test-case from @ChALkeR above does seem to get fixed.

New builds with the extra commit are available here: https://nodejs.org/download/test/v4.3.2-test2016032010820d8910/

please test folks!

@rvagg

Using the build provided by @rvagg in development benchmarks dramatically reduces the memory footprint of creating and tearing down VMs over time. This fix is a huge boon for our team! Thank you!

I'm looking to do a test with 5.9.1 later this week. I've seen good results locally but need to kick the tyres more with a % of production traffic to be certain.

If things turn out to be good with this in 5.9.1 then I don't see any reason they won't be applied to a v4 release soonish. Given that it turned out to be not quite as simple (regression in 5.9.0) it might be something we want to sit on for a little longer to ensure that the functionality is stable in v5 before we have confidence to pull it back. / @nodejs/lts

@rvagg

+1 to that @rvagg

I would love to see these changes backported, but would also like to see them mature a little longer in v5.

Finally had chance to test this - I was able to do an initial non-prod performance test. Metrics look good. I saw an overall drop in CPU and memory is reduced. I'm hoping to do a realistic prod test in the next couple of days but so far I am very happy with the results.

Thanks for looking into this.

I should clarify that those peaks are expected in my particular use case. That is actually when node-vm is executing.

Cool. So this can be closed, right?

Closing this as it's not reproducable anymore and seems to be fixed.

--expose-gc issue is at #3249.

PR to get this in to v4.x: #6871

Released in v4.4.5 folks: https://nodesource.com/blog/node-js-v4-4-5-release-brief/

Navigation Menu

Repository navigation

VM: Extreme memory growth #3113

32 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

VM: Extreme memory growth #3113

Description

Activity

ChALkeR commented on Sep 29, 2015

bnoordhuis commented on Sep 29, 2015

arthurschreiber commented on Sep 29, 2015

bnoordhuis commented on Sep 29, 2015

arthurschreiber commented on Sep 29, 2015

ChALkeR commented on Sep 29, 2015

ChALkeR commented on Sep 29, 2015

arthurschreiber commented on Sep 29, 2015

ChALkeR commented on Sep 29, 2015

ChALkeR commented on Sep 29, 2015

ChALkeR commented on Sep 29, 2015

ChALkeR commented on Sep 29, 2015

arthurschreiber commented on Sep 29, 2015

32 remaining items

ofrobots commented on Mar 16, 2016

ofrobots commented on Mar 16, 2016

rvagg commented on Mar 16, 2016

ofrobots commented on Mar 20, 2016

rvagg commented on Mar 20, 2016

cin210 commented on Mar 29, 2016

indieisaconcept commented on Mar 29, 2016

rvagg commented on Mar 29, 2016

MylesBorins commented on Mar 30, 2016

indieisaconcept commented on Apr 6, 2016

eljefedelrodeodeljefe commented on Apr 6, 2016

ChALkeR commented on Apr 14, 2016

rvagg commented on May 19, 2016

rvagg commented on May 25, 2016

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions