Memory leak issue when using programmatically with pino@8.7.0

[harbu]

Versions

• OS Linux 6.0.11
• Node.js v16.14.2
• NPM 9.1.3
• pino 8.7.0
• pino-pretty 9.1.1

Issue

Hello, firstly thank for your continuing effort on maintaining and developing this library.

Memory gets leaked on my machine when using pino-pretty 9.1.1 with pino 8.7.0. Didn't seem to be an issue before (upgrading from pino 6.11.3 and pino-pretty 5.0.2). I've set up simple repro below.

package.json

{
  "name": "pino-memory-leak",
  "version": "1.0.0",
  "description": "",
  "main": "index.js",
  "scripts": {
    "test": "echo \"Error: no test specified\" && exit 1"
  },
  "author": "",
  "license": "MIT",
  "dependencies": {
    "pino": "^8.7.0",
    "pino-pretty": "^9.1.1"
  }
}

index.mjs

import pinoPretty from 'pino-pretty'
import pino from 'pino'

function createLogger(idx) {
    const options = {
        name: `logger-${idx}`,
        enabled: true,
        level: 'debug',
        transport: {
            target: 'pino-pretty',
        }
    }
    return pino(options)
}

for (let i=0; i < 50000; ++i) {
    const logger = createLogger(i)
    logger.trace("hello")
    if (i % 100 === 0) {
        global.gc() // manually invoke garbage collection
        console.log(i)
        await new Promise((resolve) => setTimeout(resolve, 0)) // yield execution to let timers/tasks run
    }
}

Run the above with node --expose-gc index.mjs.

On my machine with 16gb RAM I get to around 1500 loggers created before memory runs out, possibly exit listeners leaking? See output below.

> node --expose-gc index.mjs
0
100
(node:14702) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 exit listeners added to [process]. Use emitter.setMaxListeners() to increase limit
(Use `node --trace-warnings ...` to show where the warning was created)
200
300
400
500
600
700
800
900
1000
1100
1200
1300
1400
1500

If you remove the pino-pretty transport from the pino options object, memory does not leak. This would lead me to suspect that the issue is possibly in pino-pretty?

Any help you could provide with this would be greatly appreciated. Sincerely, Eric

[jsumners]

You can run your reproduction through https://github.com/clinicjs/node-clinic to help learn where any leak might be occurring.

[mcollina]

Just to clarify. Is this issue about leaking memory or is it about the warning:

(node:14702) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 exit listeners added to [process]. Use emitter.setMaxListeners() to increase limit
(Use `node --trace-warnings ...` to show where the warning was created)

[harbu]

Just to clarify. Is this issue about leaking memory or is it about the warning:

(node:14702) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 exit listeners added to [process]. Use emitter.setMaxListeners() to increase limit
(Use `node --trace-warnings ...` to show where the warning was created)

Not about the warning per se. I noticed actually memory usage growing rapidly on my machine. The warning was just something incidental that may (or may not) be related.

I'll have a go of running this with node-clinic when I get a chance.

[harbu]

A few findings.

I tried using node-clinic to analyze the leak but the tool doesn't provide a report in a reasonable time frame, it's basically stuck on

Received Ctrl+C, closing process...

So alternatively I tired diagnosing the issue with chromium debugger. My finding is that memory doesn't seem to get leaked. If you give the event loop enough time (i.e. increase the sleep time)

await new Promise((resolve) => setTimeout(resolve, 10 * 1000)) // yield execution to let timers/tasks run

the heap will get eventually freed and the memory usage will hover at a more or less constant level. So looks like the problem with memory consumption comes into effect when you create too many loggers in a short time frame.

What I noticed is that creating child loggers works just great and doesn't involve as large memory costs. So my solution here most likely is to start using child loggers instead as there seems to be no issue with memory usage with them.

By the way, I enabled flag --trace-warnings to see what was causing those warnings and it seems to be related to pino more than pino-pretty:

(node:11488) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 exit listeners added to [process]. Use emitter.setMaxListeners() to increase limit
    at _addListener (node:events:601:17)
    at process.addListener (node:events:623:10)
    at buildStream (/home/harbu/work/pino-memory-leak/node_modules/pino/lib/transport.js:32:11)
    at transport (/home/harbu/work/pino-memory-leak/node_modules/pino/lib/transport.js:110:10)
    at normalizeArgs (/home/harbu/work/pino-memory-leak/node_modules/pino/lib/tools.js:291:16)
    at pino (/home/harbu/work/pino-memory-leak/node_modules/pino/pino.js:86:28)
    at createLogger (file:///home/harbu/work/pino-memory-leak/index.mjs:13:12)
    at file:///home/harbu/work/pino-memory-leak/index.mjs:21:25

So a TLDR; use childLoggers when creating multiple loggers.

[jsumners]

So my solution here most likely is to start using child loggers instead as there seems to be no issue with memory usage with them.

I suspected that was the case from your example, but decided to assume you were just trying to induce the error with that example. Yes, you shouldn't be creating a completely new pino instance for every place you want a "new" logger that is roughly the same as the old one (i.e. they are initialized the same way, just used in different contexts). That is exactly what child loggers are for.

[mcollina]

Note: this is perfectly normal. The problem you are facing is that you are creating 50000 loggers with an associated worker thread: this means creating 5000 threads. Creating a thread is an asynchronous operation, and they won't be able to be collected before it's initialized (so everything is shut down properly). Therefore you have a perceived memory leak.

Do not create 5000 threads.