The Cost of LoggingTheCostofLoggingTheCostofLogging
2 Aug 2016
Share
At NearForm, we like to scratch our own itch, and we build tools based on the needs of our customers and our own needs as consultants. When David Mark Clements and myself were in London conducting a performance training and consulting engagement with Net-A-Porter, we noticed that the routes which were logging more were the slowest ones. Moreover, disabling logging allowed far greater performance.
We started a quest to assess the cost of logging.
As a format, JSON is easy to process, and at nearForm we favour it as a logging format, so fast JSON logging had to be the goal.
As in any performance consultancy, we establish a baseline considering the simplest express application (we used node v4 throughout this post):
'use strict'</p><p>var app = require('express')()
var http = require('http')
var server = http.createServer(app)</p><p>app.get('/', function (req, res) {
res.send('hello world')
})</p><p>server.listen(3000)
text
In order to measure this, we will use autocannon, an HTTP/1.1 benchmarking tool inspired by wrk and built in Node.js:
Let’s see what happens when we add logging (in all the following example, we will be redirecting the output from stdout to /dev/null):
'use strict'</p><p>var app = require('express')()
var http = require('http')
var server = http.createServer(app)</p><p>app.use(require('express-bunyan-logger')())</p><p>app.get('/', function (req, res) {
res.send('hello world')
})</p><p>server.listen(3000)
text
We would expect this to have similar throughput to the first one. However we got some surprising results:
Running a server using bunyan for logging will reduce throughput by almost 80%. Winston yields slightly better results:
'use strict'</p><p>var app = require('express')()
var http = require('http')
var winston = require('winston')
var winstonExpress = require('express-winston')
var server = http.createServer(app)</p><p>app.use(winstonExpress.logger({
transports: [
new winston.transports.Console({
json: true
})
]
}))</p><p>app.get('/', function (req, res) {
res.send('hello world')
})</p><p>server.listen(3000)</p><p>$ autocannon -c 100 -d 5 https://localhost:3000
Running 5s test @ https://localhost:3000
100 connections with 1 pipelining factor</p><p>Stat Avg Stdev Max
Latency (ms) 28.81 8.5 149
Req/Sec 3400 425.02 3703
Bytes/Sec 711.34 kB 88.54 kB 786.43 kB</p><p>20k requests in 5s, 4.28 MB read
text
Running a server using Winston (version 2) for logging will slow you down by at least 50%.
As part of our consultancy, Dave and myself were asked for a fast alternative, and there wasn’t one. Therefore we set ourselves to the task of writing the fastest possible Node.js logger we could manage. We wanted to build something that could easily replace Winston, Bunyan (or even Bole).
Introducing Pino
Our logger is Pino, named after pine in Italian, because there is a pine in front of my house. Bunyan was a giant lumberjack, and Pino is (99%) API-compliant with Bunyan and Bole.
Pino is the fastest logger for Node.js (full benchmarks found here and here). While you can use Pino directly, you will likely use it with a Web framework, such as express or hapi.
pino-http: barebone logger for node http module, basis of express, koa and restify integrations
pino-socket: forwards pino logs over a TCP or UDP socket
Conclusion
Pino is the fastest logger in town (see the benchmarks), and it uses a full set of performance optimizations to achieve this goal, from avoiding JSON.stringify, to rolling our own printf style formatting module and flattening strings. These techniques reduce the overhead of logging by 40%. In extreme mode, we also delay flushing to disk, to reduce it even more, by 60%. We have adopted Pino in some projects, and it has increased the throughput (req/s) of those applications by a factor of 20-100%. Stay tuned for more blog posts on the techniques that Pino uses to be so fast, as each of those has its own story.
