High CPU usage when enabling"prettyPrint"

KingRial commented 6 years ago

Please tell us about your environment:

winston@3.0.0
node 8.11.3
Windows 10
ES6

What is the problem?

When having intense logging using multiple JSON structures and prettyPrint option enabled, winston would spike the CPU to 90%+

Using the following configured transport to reproduce the problem:

new (winston.transports.Console)({
          level: 'silly',
          silent: false,
          colorize: true,
          prettyPrint: true,
          timestamp: true,
          humanReadableUnhandledException: true,
          format: format.combine(
            format.splat(),
            format.colorize(),
            format.label({ label: 'Foo' }),
            format.timestamp(),
            format.prettyPrint(),
            format.printf( log => {
              return '[ ' + log.timestamp + ' ][ ' + log.level + ' ][ ' + log.label + ' ] ' + log.message;
            })
          )
        })

What do you expect to happen instead?

No CPU spike using Winston and prettyPrint enabled

Other information

By disabling the prettyPrint or using stringified versions of the JSON structures before logging, the CPU spikes disappear completly.

Modified transport configuration to solve the CPU spikes:

new (winston.transports.Console)({
          level: 'silly',
          silent: false,
          colorize: true,
          prettyPrint: false, // Forced disabled pretty print
          timestamp: true,
          humanReadableUnhandledException: true,
          format: format.combine(
            format.splat(),
            format.colorize(),
            format.label({ label: 'Foo' }),
            format.timestamp(),
            //format.prettyPrint(), // Removed prettyPrint from format
            format.printf( log => {
              return '[ ' + log.timestamp + ' ][ ' + log.level + ' ][ ' + log.label + ' ] ' + log.message;
            })
          )
        })

DABH commented 6 years ago

How deep/complicated are your JSON objects? util.inspect, which is what we use for pretty print, could become very slow for sufficiently complicated objects (maybe even infinite loop if there are cyclical structures). Do you need to log your entire object, or would you be happy with just the first few layers of it (depth parameter)?

KingRial commented 6 years ago

Right now the JSON structures I am logging are essentially an array of objects; objects are instanced classes, their number are from 10 to 100 items and their complexity never reaches a depth level of 3 (no cyclical structures).

However I log them very often: reaching the max frequency of one log each 200/500 ms.

The logging of complex structures is only usefull on development environment when using "silly" verbosity. Since the "silly" verbosity should be "silly" enough (^^), I just solved by disabling the pretty print and obtain all the complex data without any depth limit, delay or heavy CPU usage.

I didn't know "util.inspect" could be so slow compared to a JSON.stringify; problably a depth parameter could be enough to remove the spike (I could test it on my spare time if you need more data to understand better the situation)

DABH commented 6 years ago

I'm going to leave this open because we should add some docs to winston or logform.

From the Node.js docs on util.inspect (https://nodejs.org/api/util.html#util_util_inspect_object_options):

Please note that util.inspect() is a synchronous method that is mainly intended as a debugging tool. Some input values can have a significant performance overhead that can block the event loop. Use this function with care and never in a hot code path.

So Node recommends not using that in production code, hence we should probably mention somewhere that users shouldn't use prettyPrint in production code. That said, I bet if we exposed a depth parameter for prettyPrint, it could help performance.

Thanks for bringing this up, I think it's an important note!

winstonjs / winston