Memory leak in cls-hooked or wrong use?

user_7358096 0
Viewed 3187

The following code increases memory usage until crash:

const httpContext = require('express-http-context');
async function t2() {
}

async function t1() {
  for (let i = 0; i < 100000000; i++) {
    httpContext.ns.run(t2);
  }
}
t1();

run it with: node --inspect --max-old-space-size=300 ns

The problem: The namespace _contexts map is never cleaned up.

There is a function destroy(id) inside cls-hooked/context.js but that it is never called.

I tried also ns.bind, ns.runPromise (which does a ns.exit()) and ns.bind

How can I delete the contexts after a run is finished?

The code:

const httpContext = require('express-http-context');
function t2() {
}

async function t1() {
  for (let i = 0; i < 100000000; i++) {
    httpContext.ns.run(t2);
  }
}
t1();

works.

The code:

const httpContext = require('express-http-context');
async function t3() {
}
function t2() {
  t3();
}

async function t1() {
  for (let i = 0; i < 100000000; i++) {
    httpContext.ns.run(t2);
  }
}
t1();

has the memory leak again.

The cls-hooked async_hook method init() adds the context to the _contexts map. The cls-hooked async_hook method destroy() deletes the context from the _contexts map.

The problem is that destroy is never called.

Is this a bug in cls-hooked or an incompatibility to the current async_hooks?

cls-hooked express node.js
1 Answers

As pointed out to OP, the usage is definitely incorrect.

OP should only execute ns.run() once, and everything within that run will be of the same context.

Look at this example of proper usage:

var createNamespace = require('cls-hooked').createNamespace;
 
var writer = createNamespace('writer');
writer.run(function () {
  writer.set('value', 0);
 
  requestHandler();
});
 
function requestHandler() {
  writer.run(function(outer) {
    // writer.get('value') returns 0
    // outer.value is 0
    writer.set('value', 1);
    // writer.get('value') returns 1
    // outer.value is 1
    process.nextTick(function() {
      // writer.get('value') returns 1
      // outer.value is 1
      writer.run(function(inner) {
        // writer.get('value') returns 1
        // outer.value is 1
        // inner.value is 1
        writer.set('value', 2);
        // writer.get('value') returns 2
        // outer.value is 1
        // inner.value is 2
      });
    });
  });
 
  setTimeout(function() {
    // runs with the default context, because nested contexts have ended
    console.log(writer.get('value')); // prints 0
  }, 1000);
}

Furthermore, the implementation inside cls-hooked do show that context is destroyed via async hook callback destroy(asyncId)

destroy(asyncID) is called after the resource corresponding to asyncId is destroyed. It is also called asynchronously from the embedder API emitDestroy(). Some resources depend on garbage collection for cleanup, so if a reference is made to the resource object passed to init it is possible that destroy will never be called, causing a memory leak in the application. If the resource does not depend on garbage collection, then this will not be an issue. https://github.com/Jeff-Lewis/cls-hooked/blob/0ff594bf6b2edd6fb046b10b67363c3213e4726c/context.js#L416-L425

Here is my repo for comparison and test-run of memory usage by bombarding the server with tonnes of requests using autocannon https://github.com/Darkripper214/AsyncMemoryTest

Based on the test, there is a negligible increase in the utilization of heap (As expected, as we're processing HTTP requests).

Memory Utilization of CLS-Hooked & Async-Hook

Purpose

The repository is a miniature test to see how is memory utilized when using cls-hooked and async-hook to pass context within Node.js.

Usage

  1. npm run start for CLS-hooked server or npm run async for Async-hook server

  2. Go to Chrome and paste chrome://inspect

  3. Click inspect to access to Dev Tools of the server

devtools

  1. Go to memory tab, you may take snapshot and inspect the heap before, during and after bombarding the server with requests

  2. node benchmark.js to start bombarding server with requests. This is powered by autocannon, you may want to increase connections or duration to see the difference.

Results

CLS-hooked

Stat 1% 2.5% 50% 97.5% Avg Stdev Max
Req/Sec 839 839 871 897 870.74 14.23 839
Bytes/Sec 237kB 237kB 246kB 253kB 246kB 4.01kB 237kB

Req/Bytes counts sampled once per second (Note that this is ran with debugger attached, performance per second would be impacted)

13k requests in 15.05s, 3.68 MB read

cls-hook

cls-hooked graph

Async-Hook

Stat 1% 2.5% 50% 97.5% Avg Stdev Max
Req/Sec 300 300 347 400 346.4 31.35 300
Bytes/Sec 84.6kB 84.6kB 97.9kB 113kB 97.7kB 8.84kB 84.6kB

Req/Bytes counts sampled once per second (Note that this is ran with debugger attached & plenty of debug() messages to show how it store is destroyed, performance per second would be impacted)

5k requests in 15.15s, 1.47 MB read

async

async-graph

Edit 1

OP is complaining on the length of _context which is set every time a namespace.run() is executed. As highlighted earlier, the way OP is testing is not correct, as it is running on a loop.

The scenario that OP is complaining will only occurs when namespace.run() execute some callback that is or contain an async function.

async function t3() {} // This async function will cause _context length to not be cleared
function t2() {
  t3();
}
function t1() {
  for (let i = 0; i < 500; i++) {
    session.run(t2);
  }
}
t1();

So why _context is not cleared? This is because async function t3 won't be able to be run in the node.js event loop as the synchronous for loop is continuously running, hence the near-infinite appending of item into _context.

So to prove that this is due to this behavior, I've updated the repo to include a file cls-gc.js that can be run using npm run gc, which explicitly run garbage collection in between, and garbage collection won't affect the length of _context.

The length of _context will be long during execution of t1() and t2() as both is synchronous. However, the length of _context will be about right after the setTimeout callback is called. Please use debugger to check for this.

Length of _context will be available at the session

// process.env.DEBUG_CLS_HOOKED = true;
('use strict');
let createNamespace = require('cls-hooked').createNamespace;
let session = createNamespace('benchmark');

async function t3() {}
function t2() {
  t3();
}
function t1() {
  for (let i = 0; i < 500; i++) {
    session.run(t2);
    try {
      if (global.gc) {
        global.gc();
        console.log('garbage collection ran');
      }
    } catch (e) {
      console.log('`node --expose-gc index.js`');
      process.exit();
    }
  }
}
t1();

function t5() {
  for (let i = 0; i < 1000; i++) {
    // Check the _context here, should have length of at least 500
    session.run(t2);
    try {
      if (global.gc) {
        global.gc();
        console.log('garbage collection ran');
      }
    } catch (e) {
      console.log('`node --expose-gc index.js`');
      process.exit();
    }
  }
}
t5();

setTimeout(() => {
  console.log('here');
  // Check the _context here, length should be 0
  session.run(t2);
}, 3000);
user_145677660
Related