Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Aggressive Memory Leak #180

Closed
RHavar opened this issue Dec 23, 2014 · 32 comments
Closed

Aggressive Memory Leak #180

RHavar opened this issue Dec 23, 2014 · 32 comments

Comments

@RHavar
Copy link

RHavar commented Dec 23, 2014

I've been able to narrow down an aggressive memory leak I'm experiencing to this:

Run with: node --harmony --expose-gc filename.js

var co = require('co');

function* sleep() {
    return new Promise(function(resolve) {
        setTimeout(resolve, 1);
    });
};

co(function*() {

    for(var i = 0; true; ++i) {
        yield sleep();

        if (i % 10000 === 0) {
            global.gc();
            console.log(process.memoryUsage());
        }

    }

}).then(function() {
    console.log('finished')
}, function(err) {
    console.log('caught error: ', err.stack);
});

Sample output:

{ rss: 17420288, heapTotal: 9620736, heapUsed: 3590768 }
{ rss: 44822528, heapTotal: 49288192, heapUsed: 12972200 }
{ rss: 70955008, heapTotal: 58575616, heapUsed: 21688912 }
{ rss: 80048128, heapTotal: 66831104, heapUsed: 30531560 }
{ rss: 89157632, heapTotal: 76118528, heapUsed: 39490184 }
{ rss: 98275328, heapTotal: 85405952, heapUsed: 48445040 }
{ rss: 107368448, heapTotal: 93661440, heapUsed: 57410024 }
{ rss: 116477952, heapTotal: 102948864, heapUsed: 66365712 }
{ rss: 125591552, heapTotal: 112236288, heapUsed: 75330040 }
{ rss: 134684672, heapTotal: 120491776, heapUsed: 84285144 }
{ rss: 143798272, heapTotal: 129779200, heapUsed: 93250072 }
{ rss: 152907776, heapTotal: 139066624, heapUsed: 102205152 }
{ rss: 162000896, heapTotal: 147322112, heapUsed: 111170352 }
{ rss: 171114496, heapTotal: 156609536, heapUsed: 120125032 }
@zensh
Copy link
Contributor

zensh commented Dec 24, 2014

I get a similar output in co:

{ rss: 17682432, heapTotal: 9620736, heapUsed: 3590272 }
{ rss: 44625920, heapTotal: 49288192, heapUsed: 12973864 }
{ rss: 70737920, heapTotal: 58575616, heapUsed: 21691096 }

And I have tested thunks, it have a stable memory used.

➜  thunks git:(master) node --harmony --expose-gc debug/memory.js
{ rss: 17620992, heapTotal: 9620736, heapUsed: 3604664 }
{ rss: 22335488, heapTotal: 10640640, heapUsed: 4070544 }
{ rss: 22487040, heapTotal: 10640640, heapUsed: 4119704 }
{ rss: 21393408, heapTotal: 10640640, heapUsed: 3894792 }
{ rss: 22355968, heapTotal: 10640640, heapUsed: 3718848 }
var thunk = require('thunks')();

function* sleep() {
  return new Promise(function(resolve) {
    setTimeout(resolve, 1);
  });
}

thunk(function*() {

  for(var i = 0; true; ++i) {
    yield sleep();

    if (i % 10000 === 0) {
      global.gc();
      console.log(process.memoryUsage());
    }

  }

})(function(error) {
  console.log('finished', error);
});

@zensh
Copy link
Contributor

zensh commented Dec 24, 2014

I guess that all promises have been chained together, so can‘t be GC.

@fengmk2
Copy link
Collaborator

fengmk2 commented Dec 24, 2014

I test on co@v3 and co@v4, v4 cause leak and v3 no. And also found out v3 run faster a lot than v4.

v4

$ node --harmony --expose-gc gc.js 
{ rss: 17715200, heapTotal: 9620736, heapUsed: 3586336 }
{ rss: 22806528, heapTotal: 11672576, heapUsed: 4875672 }
{ rss: 24219648, heapTotal: 16898816, heapUsed: 5799440 }
{ rss: 26984448, heapTotal: 17930752, heapUsed: 6477960 }
{ rss: 29409280, heapTotal: 18962688, heapUsed: 7198408 }
{ rss: 30322688, heapTotal: 19994624, heapUsed: 8082112 }
{ rss: 31219712, heapTotal: 19994624, heapUsed: 8980632 }
{ rss: 32292864, heapTotal: 29415168, heapUsed: 9874232 }
{ rss: 33206272, heapTotal: 30447104, heapUsed: 10772656 }
{ rss: 34119680, heapTotal: 31479040, heapUsed: 11666184 }
{ rss: 35033088, heapTotal: 32510976, heapUsed: 12564688 }
{ rss: 35946496, heapTotal: 33542912, heapUsed: 13458168 }
{ rss: 36855808, heapTotal: 34574848, heapUsed: 14356664 }
{ rss: 37761024, heapTotal: 34574848, heapUsed: 15250944 }
{ rss: 38670336, heapTotal: 35606784, heapUsed: 16149576 }
{ rss: 39583744, heapTotal: 36638720, heapUsed: 17043008 }
{ rss: 40497152, heapTotal: 37670656, heapUsed: 17941504 }
{ rss: 41738240, heapTotal: 55479808, heapUsed: 18835008 }
{ rss: 42651648, heapTotal: 56511744, heapUsed: 19733504 }
{ rss: 43565056, heapTotal: 57543680, heapUsed: 20627016 }
{ rss: 44474368, heapTotal: 58575616, heapUsed: 21525504 }
{ rss: 45375488, heapTotal: 58575616, heapUsed: 22418944 }
{ rss: 46284800, heapTotal: 59607552, heapUsed: 23317744 }
{ rss: 47198208, heapTotal: 60639488, heapUsed: 24211624 }
{ rss: 48111616, heapTotal: 61671424, heapUsed: 25110384 }
{ rss: 49025024, heapTotal: 62703360, heapUsed: 26004080 }
{ rss: 49938432, heapTotal: 63735296, heapUsed: 26902584 }
{ rss: 50847744, heapTotal: 64767232, heapUsed: 27796264 }
{ rss: 51748864, heapTotal: 64767232, heapUsed: 28694296 }
{ rss: 52662272, heapTotal: 65799168, heapUsed: 29593040 }
{ rss: 53575680, heapTotal: 66831104, heapUsed: 30491640 }
{ rss: 54489088, heapTotal: 67863040, heapUsed: 31385736 }
{ rss: 55402496, heapTotal: 68894976, heapUsed: 32284688 }
{ rss: 56315904, heapTotal: 69926912, heapUsed: 33179120 }
{ rss: 57241600, heapTotal: 70958848, heapUsed: 34091464 }
{ rss: 58150912, heapTotal: 71990784, heapUsed: 34986672 }
{ rss: 59068416, heapTotal: 73022720, heapUsed: 35884920 }
{ rss: 59961344, heapTotal: 73022720, heapUsed: 36778776 }
{ rss: 60870656, heapTotal: 74054656, heapUsed: 37677176 }
{ rss: 61784064, heapTotal: 75086592, heapUsed: 38570896 }
{ rss: 62697472, heapTotal: 76118528, heapUsed: 39469144 }
{ rss: 63610880, heapTotal: 77150464, heapUsed: 40364008 }
{ rss: 64524288, heapTotal: 78182400, heapUsed: 41262688 }
{ rss: 65437696, heapTotal: 79214336, heapUsed: 42156024 }
{ rss: 66338816, heapTotal: 79214336, heapUsed: 43058560 }
{ rss: 67248128, heapTotal: 80246272, heapUsed: 43952192 }
{ rss: 68161536, heapTotal: 81278208, heapUsed: 44850680 }
{ rss: 69074944, heapTotal: 82310144, heapUsed: 45744312 }
{ rss: 69992448, heapTotal: 83342080, heapUsed: 46642592 }
{ rss: 70909952, heapTotal: 84374016, heapUsed: 47536112 }
{ rss: 71815168, heapTotal: 85405952, heapUsed: 48434648 }
{ rss: 72712192, heapTotal: 85405952, heapUsed: 49328112 }
{ rss: 73629696, heapTotal: 86437888, heapUsed: 50226432 }
{ rss: 74534912, heapTotal: 87469824, heapUsed: 51120328 }
{ rss: 75452416, heapTotal: 88501760, heapUsed: 52018432 }

v3

$ node --harmony --expose-gc co-gc.js 
{ rss: 17379328, heapTotal: 9620736, heapUsed: 3584488 }
{ rss: 22138880, heapTotal: 10640640, heapUsed: 4091872 }
{ rss: 22167552, heapTotal: 10640640, heapUsed: 4120112 }
{ rss: 26386432, heapTotal: 14834944, heapUsed: 3897544 }
{ rss: 26390528, heapTotal: 14834944, heapUsed: 3680472 }
{ rss: 26198016, heapTotal: 14834944, heapUsed: 3668624 }
{ rss: 26214400, heapTotal: 14834944, heapUsed: 3679640 }
{ rss: 26226688, heapTotal: 14834944, heapUsed: 3676720 }
{ rss: 26243072, heapTotal: 14834944, heapUsed: 3689608 }
{ rss: 26243072, heapTotal: 14834944, heapUsed: 3684136 }
{ rss: 26243072, heapTotal: 14834944, heapUsed: 3675280 }
{ rss: 26243072, heapTotal: 14834944, heapUsed: 3695656 }
{ rss: 26247168, heapTotal: 14834944, heapUsed: 3684976 }
{ rss: 26259456, heapTotal: 14834944, heapUsed: 3717544 }
{ rss: 26267648, heapTotal: 14834944, heapUsed: 3677712 }
{ rss: 26267648, heapTotal: 14834944, heapUsed: 3725896 }
{ rss: 26275840, heapTotal: 14834944, heapUsed: 3669344 }
{ rss: 26275840, heapTotal: 14834944, heapUsed: 3699792 }
{ rss: 28626944, heapTotal: 23223552, heapUsed: 3689304 }
{ rss: 34664448, heapTotal: 23223552, heapUsed: 3708152 }
{ rss: 34664448, heapTotal: 23223552, heapUsed: 3665304 }
{ rss: 34664448, heapTotal: 23223552, heapUsed: 3696728 }
{ rss: 34672640, heapTotal: 23223552, heapUsed: 3677392 }
{ rss: 34672640, heapTotal: 23223552, heapUsed: 3676784 }
{ rss: 34672640, heapTotal: 23223552, heapUsed: 3715400 }
{ rss: 34672640, heapTotal: 23223552, heapUsed: 3674608 }
{ rss: 34684928, heapTotal: 23223552, heapUsed: 3690264 }
{ rss: 34689024, heapTotal: 23223552, heapUsed: 3728336 }
{ rss: 34734080, heapTotal: 24255488, heapUsed: 3699928 }
{ rss: 34795520, heapTotal: 24255488, heapUsed: 3699496 }
{ rss: 34795520, heapTotal: 24255488, heapUsed: 3691256 }
{ rss: 34799616, heapTotal: 24255488, heapUsed: 3703848 }
{ rss: 34820096, heapTotal: 24255488, heapUsed: 3743168 }
{ rss: 34820096, heapTotal: 24255488, heapUsed: 3678752 }
{ rss: 34820096, heapTotal: 24255488, heapUsed: 3698752 }
{ rss: 34820096, heapTotal: 24255488, heapUsed: 3701112 }
{ rss: 34885632, heapTotal: 25287424, heapUsed: 3727984 }
{ rss: 34811904, heapTotal: 24255488, heapUsed: 3712672 }
{ rss: 34811904, heapTotal: 24255488, heapUsed: 3684448 }
{ rss: 34811904, heapTotal: 24255488, heapUsed: 3679704 }
{ rss: 34811904, heapTotal: 24255488, heapUsed: 3755208 }
{ rss: 34811904, heapTotal: 24255488, heapUsed: 3718944 }
{ rss: 34811904, heapTotal: 24255488, heapUsed: 3705672 }
{ rss: 34811904, heapTotal: 24255488, heapUsed: 3687176 }
{ rss: 34816000, heapTotal: 24255488, heapUsed: 3716064 }
{ rss: 34816000, heapTotal: 24255488, heapUsed: 3696856 }
{ rss: 34816000, heapTotal: 24255488, heapUsed: 3690104 }
// ....
{ rss: 45645824, heapTotal: 41032704, heapUsed: 3806672 }
{ rss: 45719552, heapTotal: 42064640, heapUsed: 3819824 }
{ rss: 45600768, heapTotal: 41032704, heapUsed: 3770720 }
{ rss: 45600768, heapTotal: 41032704, heapUsed: 3767880 }
{ rss: 45600768, heapTotal: 41032704, heapUsed: 3835928 }
{ rss: 45600768, heapTotal: 41032704, heapUsed: 3827312 }
{ rss: 45600768, heapTotal: 41032704, heapUsed: 3780216 }

@fengmk2
Copy link
Collaborator

fengmk2 commented Dec 24, 2014

I use heapdump find out Promise objects are leak.

image

@fengmk2
Copy link
Collaborator

fengmk2 commented Dec 24, 2014

gc test codes with heapdump:

var co = require('co');
var heapdump = require('heapdump');

function* sleep() {
  return new Promise(function(resolve) {
    setTimeout(resolve, 1);
  });
}

co(function*() {

  for(var i = 0; true; ++i) {
    yield sleep();

    if (i % 1000 === 0) {
      global.gc();
      console.log(process.memoryUsage());
      heapdump.writeSnapshot();
    }

  }

}).then(function() {
  console.log('finished')
}, function(err) {
  console.log('caught error: ', err.stack);
});

@fengmk2
Copy link
Collaborator

fengmk2 commented Dec 24, 2014

https://github.com/tj/co/blob/master/index.js#L88 if (ret.done) return Promise.resolve(ret.value); never in, so Promise chain can not be GC.

@hit9
Copy link

hit9 commented Dec 24, 2014

@fengmk2 Nice. I use co4 the following way:

for (..) {  // or while (true)
  yield working
}

and I find Promise wasn't be gc, So I switch to process.nextTick, and the memory leaks went away.

function *work() {
  yield working
  process.nextTick(co.wrap(function *() {
    yield work();
  });
}

@hit9
Copy link

hit9 commented Dec 24, 2014

@fengmk2 if (ret.done) return Promise.resolve(ret.value); never in? Really? My test result didnt meet yours..

@jonathanong
Copy link
Contributor

only solution i can think of is the co equivalent of a "maximum call stack exceeded" error. nothing else we could really do. hopefully tc39 makes promises more gc-friendly. hopefully this won't happen in es7 async/await.

@jonathanong
Copy link
Contributor

personally i would just make work() return a promise and never resolve them against each other.

var work = co.wrap(function* () {
  yield dostuff()
  work().catch(onerror)
})

// don't ever let an error crash anything
function onerror(err) {
  console.error(err.stack)
}

// start working
work().catch(onerror)

hell you don't even need to use co to do this:

work()
function work() {
  doSomething().catch(onerror).then(work)
}

@domenic
Copy link

domenic commented Dec 25, 2014

I don't fully understand what's going on here, but I think this is a V8 bug. Promises are not supposed to hold references to each other in a chain. They should always follow the chain to the ultimate value, which might be a currently-pending promise, or will be a rejection reason/fulfillment value. I believe V8's implementation fails at this currently.

If you can produce a smaller repro, without co or generators but instead just a long promise chain, that would be helpful. You can then test against a simple implementation like e.g. then/promise and show that the memory does not leak there. If that's the case then it's time to report a V8 bug.

@jonathanong
Copy link
Contributor

well personally i don't see how it could be gc'd, but i'm not computer scientist. what's essentially happening is that a long chain of never-resolved promises are created. what we've got is:

next()
function next() {
  return new Promise(function (resolve) {
    setImmediate(resolve)
  }).then(next)
}

which is basically the following, but on separate ticks:

next()
function next() {
  return Promise.resolve(next())
}

@domenic
Copy link

domenic commented Dec 25, 2014

But the chain should never be of length longer than 2. Let's give things names.

var p1 = Promise.resolve();
var p2 = Promise.resolve(p1);

// p2 should not hold reference to p1, because it just knows to fulfill with undefined

var q1 = new Promise(() => {}); // forever-pending
var q2 = Promise.resolve(q1); // holds reference to q1
var q3 = Promise.resolve(q2);

// q3 should hold a reference to q1, but not to q2; it should follow to the source.

@domenic
Copy link

domenic commented Dec 25, 2014

Oh I see, I seem to be talking about something entirely different. I wrote out your scenario longhand and ugh that does seem bad.

Maybe it will seem better in the morning, I should sleep now :-/

@jonathanong
Copy link
Contributor

okay here's a smaller promise-only test-case and its result:

var i = 0
next()
function next() {
  return new Promise(function (resolve) {
    i++
    if (i % 100000 === 0) {
      global.gc();
      console.log(process.memoryUsage());
    }
    setImmediate(resolve)
  }).then(next)
}
{ rss: 142749696, heapTotal: 128759296, heapUsed: 93098624 }
{ rss: 234614784, heapTotal: 218537728, heapUsed: 182771736 }
{ rss: 325664768, heapTotal: 308316160, heapUsed: 272393200 }
{ rss: 416694272, heapTotal: 397062656, heapUsed: 361990640 }
{ rss: 507744256, heapTotal: 486841088, heapUsed: 451476544 }
{ rss: 598794240, heapTotal: 576619520, heapUsed: 541064768 }
{ rss: 688660480, heapTotal: 666397952, heapUsed: 630666888 }
{ rss: 779710464, heapTotal: 756176384, heapUsed: 720264424 }
{ rss: 870760448, heapTotal: 845954816, heapUsed: 809866824 }
{ rss: 961794048, heapTotal: 934701312, heapUsed: 899464696 }
{ rss: 1052844032, heapTotal: 1024479744, heapUsed: 989066688 }
{ rss: 1143898112, heapTotal: 1114258176, heapUsed: 1078667208 }
{ rss: 1234948096, heapTotal: 1204036608, heapUsed: 1168269624 }
{ rss: 1325998080, heapTotal: 1293815040, heapUsed: 1257867232 }
{ rss: 1417052160, heapTotal: 1383593472, heapUsed: 1347469472 }

spion added a commit to spion/co that referenced this issue Dec 25, 2014
Fixed tj#180 by switching to a procedural implementation instead of
building up an entire promise chain of all the values yielded by the
generator.
spion added a commit to spion/co that referenced this issue Dec 25, 2014
Fixes tj#180 by switching to a procedural implementation instead of
building up an entire promise chain of all the values yielded by the
generator.
zensh added a commit to zensh/co that referenced this issue Dec 25, 2014
@zensh
Copy link
Contributor

zensh commented Dec 27, 2014

This patch has gained 20% performance in sync test.

ruimarinho pushed a commit to seegno-forks/koa that referenced this issue Jan 3, 2015
This version includes an important fix for a memory leak.

See tj/co#180.
ruimarinho pushed a commit to seegno-forks/koa that referenced this issue Jan 3, 2015
This version includes an important fix for a memory leak.

See tj/co#180.
@hax
Copy link

hax commented Jan 5, 2015

@jonathanong
V8 bug?
But I tested Chrome 39, it seems already be fixed.

@dead-horse
Copy link
Contributor

@hax you should read this: promises-aplus/promises-spec#179

As they discussed, it's a bug in spec, bluebird and then/promise already fixed this in their implementations, but these patches don't follow the spec.

@jonathanong
Copy link
Contributor

if someone wants to test the old version in iojs/master... :D

@fengmk2
Copy link
Collaborator

fengmk2 commented Jan 19, 2015

I use co@~4.10 still got memory leak if we remove global.gc();.

Test scripts https://gist.github.com/fengmk2/8fdbd896fee458efe0b4

@hax
Copy link

hax commented Jan 19, 2015

@fengmk2 V8 only gc if short of memory.

@yanickrochon
Copy link

@fengmk2 a memory leak is when calling the garbage collector does not work as expected. Garbage collecting is an heavy process that may slow the program down, so V8 (as other languages using gc) calls it automatically when short of memory, or if idle (i.e. waiting for IO or something), or when the engine notices an increase in orphan objects (i.e. ready to be gc'd), etc. In the sample you provided, you see that memory is, indeed, garbage collected at some point. You have to compare memory usage at startup, and monitor peaks; these peaks should not increase excessively during a burn-in test.

@petkaantonov
Copy link

I use co@~4.10 still got memory leak if we remove global.gc();.

If calling global.gc() frees memory then it's not a memory leak.

@undoZen
Copy link

undoZen commented Jan 21, 2015

@fengmk2 I tried run your demo (https://gist.github.com/fengmk2/8fdbd896fee458efe0b4) in a memory limited container (iojs/latest), gc triggered when limit reached.

@dead-horse
Copy link
Contributor

anybody can take a look at cnpm/mirrors#41?

@fengmk2
Copy link
Collaborator

fengmk2 commented Jan 21, 2015

@undoZen the memory limit value is 100mb, 200mb or 1gb?

@undoZen
Copy link

undoZen commented Jan 22, 2015

@fengmk2 I tried 20m 22m 25m all take over 2~4m over specified limit but not gone further.

@hax
Copy link

hax commented Jan 26, 2015

@dead-horse After reading the issue (promises-aplus/promises-spec#179 ) and writing a promise implementation my self, I believe that this is NOT the spec bug, just missing an optional optimization for edge case. And I believe it's possible to optimize the promise implementation to avoid this issue while not break the right behavior about the order. I will publish my new promise implementaion to prove it soon.

@undoZen
Copy link

undoZen commented Jan 26, 2015

@hax hope you will keep your promise ... to release your promise implementation soon.

@petkaantonov
Copy link

@hax it was already proven however I don't see it as an optional optimization (memory leak is a bug) or an edge case (the pattern is the clearest one to perform for loop equivalent).

@hax
Copy link

hax commented Jan 27, 2015

@petkaantonov It seems still have some issues. The main problem is, V8 native impl (Chrome and Safari 8) and Firefox native impl show very diff behaviors. Currently Firefox may be more close to the ES6 spec as my understanding. I will post a testcase soon.

@hax
Copy link

hax commented Feb 2, 2015

I recently found that this issue is more complex than I thought, to preserve the order behavior of current ES6 draft strictly (which most implementations fail, only my-promise is ok -- I write it according to the spec draft carefully and it's the only impl passed all es6-promises-tests), it's impossible to eliminate "leak" completely, though it can be reduced to leaking only one small object (as a pointer to denote the position) for each nest promise.
So, it may be a ES6 spec "bug" if you don't treat this as edge case. But it may be not a Promise/A+ spec bug since Promise/A+ spec seems not define the order. I opened an issue promises-aplus/promises-spec#183 for more discuss.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.