Sometimes developers are hesitant to include logging due to performance concerns, but is this justified and how much does the choice of library affect performance?

Let’s run some benchmarks to find out! We ran a series of performance tests on some of the most popular NodeJS libraries. These tests are designed to show how quickly each library processed logging and the impact on the overall application.

The Contenders

For this test, we investigated some of the most commonly used NodeJS logging libraries:

• Log4js 4.0.2
• Winston 3.2.1
• Bunyan 1.8.12

We also used the following additional libraries:

• winston-syslog 2.0.1 for syslog logging with Winston
• bunyan-syslog 0.3.2 for syslog logging with Bunyan

We benchmarked these libraries to test their performance, sending their logs to a console and file system. We also tested sending log info to a local rsyslog server over both TCP and UDP since it is common and probably wise to offload logs in a production environment.

These tests were run using NodeJS 8.15.1.

Methodology

Our goal was to compare the performance between the logging libraries. Each library was run on its default configuration and the same system was used across all libraries and tests.

Our test application logged a total of 1,000,000 log events of the phrase “Hello, world!” and it’s available on GitHub at https://github.com/codejamninja/node-log-benchmarks. We strictly processed logs to create an isolated control group.

We measured the results dedicating either a single logical processor or eight (4 cores with hyperthreading) to simulate a larger production server. NodeJS is often considered a single threaded program, but technically it's just the event loop that is single threaded. There are many NodeJS tasks that take place on parallel threads, such as garbage collection. It's also worth noting that the tty (terminal) was doing a bunch of work printing the logs to the screen, which would have most definitely executed on a separate thread. That’s why is so important to test with multiple CPUs typically found on production systems.

Also, the NodeJS file system writes are nonblocking (asynchronous). The unblocked time lets us know when the code used to schedule the filesystem writes is finished and the system can continue executing additional business logic. However, the file system will still be asynchronously writing in the background. So, the done time lets us know how long it took to actually write the logs to the filesystem.

The hardware we used is from Amazon AWS.

Test Results

For all tests, the results are measured in milliseconds. The smaller bars are better because it means the logs took less time to process.

Console

For the first set of test results, we benchmarked the performance of the libraries when logging to the console.

From these results, we can see additional CPUs had a significant effect on the amount of time it took NodeJS to log to the console. Winston is the clear winner for speed in multithreaded systems; however, Bunyan performed slightly better in a single-threaded system.

Filesystem

For the second set of test results, we benchmarked the performance of the libraries when writing the logs to the filesystem. Again, notice that each test result contains two times, unblocked and done. This is because the libraries sometimes asynchronously send the logs to syslog. The total time to log is the sum of these two times.

After seeing how much additional CPUs affected console logs, I was very surprised to see that logging to the filesystem performed roughly the same with additional CPUs. This is most likely because the work required to write files is much less than the work required to print to a tty device, so there was less multithreaded activity happening.

Log4js seemed to have the worst results writing to a filesystem, sometimes taking over 5 times the amount of time to write to the filesystem. Winston unblocked the event loop the fastest, but Bunyan finished writing to the filesystem the fastest. So, if you're choosing a log library based on filesystem performance, the choice would depend on whether you want the event loop unblocked the fastest or if you want the overall program execution to finish first.

Syslog UDP

For the third set of test results, we benchmarked the performance of the libraries when sending the logs to syslog over UDP.

Log4js and Bunyan both finished around the same time when using multiple CPUs; however, Log4js unblocked the event loop much sooner and performed better on a single CPU.

Log4js also successfully sent all of its logs to syslog without dropping a single one. Although Bunyan had a low drop rate, it still managed to drop a few logs. I would say Log4js is a clear winner when sending logs to syslog over UDP.

I had a terrible experience getting Winston to work with syslog over UDP. When it did work it took well over a minute to unblock the event loop, and took over two minutes to finish sending the logs to syslog. However, most of the times I tested it, I ran out of memory before I could finish. I am assuming that when using UDP, the library aggregates all the logs in the heap before sending them to syslog, instead of immediately streaming the logs over to syslog. At any rate, it sends the logs over to syslog over UDP in a way that does not work well when slammed with a million logs.

Syslog TCP

For the fourth set of test results, we benchmarked the performance of the libraries when sending the logs to syslog over TCP. Again, notice that each test result contains two times, unblocked and done. This is because the libraries sometimes asynchronously send the logs to syslog.

Since Bunyan was the only library that successfully sent logs to syslog over TCP without dropping any of them, it is the clear winner. Despite its somewhat slow performance when multiple CPUs were introduced, it still was relatively fast.

Sadly I was not able to get Log4js to send logs to syslog over TCP. I believe there is a bug in their library. I consistently received the following error.


(node:31818) UnhandledPromiseRejectionWarning: TypeError: Cannot read property 'trace' of undefined

Winston was relatively fast when sending logs to syslog over TCP, however, it had a horrific log drop rate. Most of the logs were either dropped or corrupted. Below is an example of one of the corrupted logs syslog received from Winston. You can see that the message was cut off.

Mar 17 19:21:42 localhost /home/codejamninja/.nvm/versions/node/v8.15.1/bin/node[22463]: {"mes

The log was supposed to look like this:

Mar 17 19:21:42 localhost /home/codejamninja/.nvm/versions/node/v8.15.1/bin/node[22463]: {"message": "92342: Hello, world!"}

Bunyan performed relatively well when sending logs to syslog over TCP. It did not drop a single log and unblocked the event loop very quickly. One thing that did surprise me though is that additional CPUs consistently performed worse than running on a single CPU. I am baffled by that, though this is the only scenario in which that happened.

Conclusion

These results really took me by surprise. I was thinking there would be an overall winner, but each library performed best in different areas under different conditions.

Winston performed best when logging to the console. Winston and Bunyan both performed best in their own ways when logging to the file system. Log4js performed the best when sending logs to syslog over UDP. Bunyan had the best results when sending logs to syslog over TCP.

If you care more about throughput for syslog, then Log4js with UDP is the best output type. If you only care unblocking the code then Winston writing to a filesystem is the best. In this case, logging averaged 0.0005 ms per log event which is blazing fast. If your typical response latency is 100 ms, then it's only 0.0005% of your total response time. That’s faster than running console.log(). As long as you don’t go overboard with too many log statements, the impact is very small.

Overall, I would recommend using Log4js with UDP library for the best performance. This will have a negligible impact on your overall response time. Tools like Loggly will store and organize those logs for you. It will alert you when the system encounters critical issues so you can deliver a great experience to your customers.