Pino: Benchmarks: Compare memory usage

[glensc]

For persistent node applications, memory usage and leak is a more important factor than CPU usage.

For example, I've run into a case where Winston leaks memory after switching sentry transport, and have not found a solution to that.

Please add memory usage to benchmarks.

[jsumners]

We write directly to the output stream unless async mode is turned on (https://github.com/pinojs/pino/blob/e616c1c7fa8cce2f7071ed7ba14cf68f2997f4b5/docs/api.md#pino-destination). If async mode is turned on, then we buffer 4096 bytes at a time by default (https://github.com/pinojs/pino/blob/e616c1c7fa8cce2f7071ed7ba14cf68f2997f4b5/docs/asynchronous.md). What would you like to see benchmarked?

Would you like to send a PR to add the benchmarks you are interested in?

[glensc]

I've tested something like this with winston:

  let mu = process.memoryUsage();
  logger.warn(`Starting memoryUsage test. RSS: ${mu.rss}, heap: ${mu.heapUsed}`);

  for (let i = 1; i < 196000; i += 1) {
    mu = process.memoryUsage();
    logger.debug(`${i}. memoryUsage: RSS: ${mu.rss}, heap: ${mu.heapUsed}`);
    if (i % 14000 === 0) {
      logger.info(`${i}. memoryUsage: RSS: ${mu.rss}, heap: ${mu.heapUsed}`);
    }
  }

and it leaks quite fast:

2020-10-20 13:30:34 [warn]:     Starting memoryUsage test. RSS: 145657856, heap: 74832728
2020-10-20 13:30:34 [info]:     14000. memoryUsage: RSS: 151818240, heap: 85091080
2020-10-20 13:30:35 [info]:     28000. memoryUsage: RSS: 157609984, heap: 91412464
2020-10-20 13:30:35 [info]:     42000. memoryUsage: RSS: 163037184, heap: 96604992
2020-10-20 13:30:35 [info]:     56000. memoryUsage: RSS: 168660992, heap: 102128024
2020-10-20 13:30:35 [info]:     70000. memoryUsage: RSS: 174440448, heap: 107699672
2020-10-20 13:30:35 [info]:     84000. memoryUsage: RSS: 180203520, heap: 113362584
2020-10-20 13:30:36 [info]:     98000. memoryUsage: RSS: 185999360, heap: 118993096
2020-10-20 13:30:36 [info]:     112000. memoryUsage: RSS: 191782912, heap: 124661392
2020-10-20 13:30:36 [info]:     126000. memoryUsage: RSS: 197566464, heap: 130294024
2020-10-20 13:30:36 [info]:     140000. memoryUsage: RSS: 203333632, heap: 135911344
2020-10-20 13:30:36 [info]:     154000. memoryUsage: RSS: 209113088, heap: 141516744
2020-10-20 13:30:37 [info]:     168000. memoryUsage: RSS: 214913024, heap: 147224496
2020-10-20 13:30:37 [info]:     182000. memoryUsage: RSS: 220708864, heap: 152879872

maybe the test is incorrect as VM has no chance to do GC.

[mcollina]

The problem in your snippet is that winston logs _partially_ asynchronously. There are a few nextTick involved in the process and then it depends on the destination.

Pino in sync mode guarantees no memory leaks for logging purposes at the cost of blocking the process until the write is done. Writing to stdout is not such a big deal in terms of latency - even if we loose some throughput. Asynchronous logging _will_ yield to a perceived memory leak if logging happens in a synchronous loop.

The difference between Winston and Pino is that in Pino you have fine-grained control over this. Note that this does not apply if you are using a AWS lambda or PM2 (they have different stdout implementations).