sails: Memory leak when lifting and lowering Sails repeatedly in automated tests

Node version: v10.16.0 Sails version (sails): 1.2.3 ORM hook version (sails-hook-orm): Not using this. Sockets hook version (sails-hook-sockets): Not using this. Organics hook version (sails-hook-organics): Not using this. Grunt hook version (sails-hook-grunt): Not using this. Uploads hook version (sails-hook-uploads): Not using this. DB adapter & version (e.g. sails-mysql@5.55.5): Not using this. Skipper adapter & version (e.g. skipper-s3@5.55.5): Not using this.


I’ve looked through all issued related to memory leaks, but none of them describes my case.

When testing a sails application, we ‘lift’ and ‘lower’ for each test. We have an extensive test suite, and we now experience OOM errors when running tests. We use the supported constructor as mentioned here: https://sailsjs.com/documentation/concepts/programmatic-usage

I managed to make a tiny script that clearly shows the increasing memory footprint.

const Sails = require("sails").Sails;

(async () => {
  for(let i = 0; i < 500000; i++){
    await startStop();
    if(i % 100 === 0) printUsage();
  }
})();

async function startStop() {
  const sails = new Sails();
  await sails.lift({ log: { noShip: true }, session: { secret: 'x' } });
  await sails.lower();
}

function printUsage() {
  const used = process.memoryUsage().heapUsed / 1024 / 1024;
  console.log(`Process uses ${Math.round(used * 100) / 100} MB`);
}

It takes awhile, but eventually it runs out of memory. Some memory is clearly being freed by the garbage collector, but some is never freed. Output from my console is:

ath88@lipton:~/test/sails-test$ node index.js 
Process uses 23.84 MB
Process uses 29.99 MB
Process uses 34.82 MB
...
Process uses 1271.33 MB
Process uses 1286.41 MB
Process uses 1287.27 MB

<--- Last few GCs --->

[11916:0x348d020]   500144 ms: Mark-sweep 1239.6 (1418.2) -> 1239.6 (1395.2) MB, 713.7 / 0.1 ms  (average mu = 0.830, current mu = 0.000) last resort GC in old space requested
[11916:0x348d020]   500840 ms: Mark-sweep 1239.6 (1395.2) -> 1239.6 (1395.2) MB, 695.9 / 0.1 ms  (average mu = 0.711, current mu = 0.000) last resort GC in old space requested

<--- JS stacktrace --->

==== JS stack trace =========================================

    0: ExitFrame [pc: 0xf994af5be1d]
    1: StubFrame [pc: 0xf994af5a1bb]
Security context: 0x345970a9e6e9 <JSObject>
    2: set [0x345970a937b9](this=0x221dd5702859 <JSWeakMap>,0x300fe1705e19 <JSFunction wrapper (sfi = 0x16c7dcce5979)>,0x300fe1705da9 <JSArray[10]>)
    3: /* anonymous */ [0x221dd57069d1] [/home/ath88/test/sails-test/node_modules/@sailshq/lodash/lib/index.js:~7645] [pc=0xf994af707d4](this=0x1e819d409ad1 <JSFunction lodash...

FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - JavaScript heap out of memory
 1: 0x8f9d10 node::Abort() [node]
 2: 0x8f9d5c  [node]
 3: 0xaffd0e v8::Utils::ReportOOMFailure(v8::internal::Isolate*, char const*, bool) [node]
 4: 0xafff44 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [node]
 5: 0xef4152  [node]
 6: 0xf0396f v8::internal::Heap::AllocateRawWithRetryOrFail(int, v8::internal::AllocationSpace, v8::internal::AllocationAlignment) [node]
 7: 0xecc9c6 v8::internal::Factory::AllocateRawArray(int, v8::internal::PretenureFlag) [node]
 8: 0xecd24a v8::internal::Factory::NewFixedArrayWithFiller(v8::internal::Heap::RootListIndex, int, v8::internal::Object*, v8::internal::PretenureFlag) [node]
 9: 0xecd2f0 v8::internal::Handle<v8::internal::FixedArray> v8::internal::Factory::NewFixedArrayWithMap<v8::internal::FixedArray>(v8::internal::Heap::RootListIndex, int, v8::internal::PretenureFlag) [node]
10: 0x10089b1 v8::internal::HashTable<v8::internal::ObjectHashTable, v8::internal::ObjectHashTableShape>::NewInternal(v8::internal::Isolate*, int, v8::internal::PretenureFlag) [node]
11: 0x1008a0e v8::internal::HashTable<v8::internal::ObjectHashTable, v8::internal::ObjectHashTableShape>::New(v8::internal::Isolate*, int, v8::internal::PretenureFlag, v8::internal::MinimumCapacity) [node]
12: 0x101926f v8::internal::HashTable<v8::internal::ObjectHashTable, v8::internal::ObjectHashTableShape>::EnsureCapacity(v8::internal::Handle<v8::internal::ObjectHashTable>, int, v8::internal::PretenureFlag) [node]
13: 0x102b618 v8::internal::ObjectHashTable::Put(v8::internal::Handle<v8::internal::ObjectHashTable>, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int) [node]
14: 0x102b836 v8::internal::JSWeakCollection::Set(v8::internal::Handle<v8::internal::JSWeakCollection>, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int) [node]
15: 0x1142060 v8::internal::Runtime_WeakCollectionSet(int, v8::internal::Object**, v8::internal::Isolate*) [node]
16: 0xf994af5be1d 
Aborted (core dumped)

As far as I can see from snapshots with Chrome DevTools, async is getting re-required and never removed from memory.

If would be awesome to eliminate this memory leak, so we can continue our testing practices, with the supported ‘programmatic usage’.

About this issue

  • Original URL
  • State: open
  • Created 5 years ago
  • Comments: 25 (12 by maintainers)

Commits related to this issue

Most upvoted comments

I think I remember back when I opened the issue, that I found something in sails that messes with require.cache.

@ath88 Great pointer, thanks - this looks like it’s spot on, at least for most of the memory leak.

I’ve adapted the examples above at https://github.com/alxndrsn/sails-memory-leak to demonstrate the memory leak, and test the effects of disabling include-all’s cache deletion for all or some of it’s calls.

Results I’m getting:

include-all deletes require.cache? heap change after 500 iterations
always 633.65 MB
never 1.28 MB
only when loading /config 633.60 MB

This require.cache-clearing seems like surprising behaviour from sails, given that node’s docs say:

Modules are cached after the first time they are loaded. This means (among other things) that every call to require('foo') will get exactly the same object returned, if it would resolve to the same file. This is an important feature.

https://nodejs.org/api/modules.html#modules_caching

Apart from the memory leak, it also means that any expectation you had that your source files will be parsed/run exactly once may be violated.

I stumbled upon that very problem when using mongoose, since it utilizes a singleton pattern stored in the modules scope. We did some database interactions before starting sails, which resulted in two connections, instead of just one.

My personal use case for lifting and lowering sails in a similar fashion, is for the setup and teardown of test. Each test should have a predictable state, unrelated to any previous tests, and therefore a clean sails application is preferred. I hope that makes sense to you. I can’t think of other use cases right now.

@johnabrams7 With both, now.

For the record - i just inserted a manual gc(), for every lift and lower, using --expose_gc, and the same pattern shows.

@ath88 I was able to reproduce the memory leak on our end and will have this further investigated with the team for what’s causing it along with a resolution. Will get back with you with further updates. 👍

Screen Shot 2019-07-12 at 5 11 39 PM Screen Shot 2019-07-12 at 5 12 18 PM

Here you go. https://github.com/ath88/sails-oom-test Just do npm i and npm start.