Original Results

Observation

Disabling logging

increased throughput

The more you log the better

Perceived time spent
logging a line

0 ms

Actual time spent
logging a line

0.22 ms

One Log Per Request

Ten Logs Per Request

We

♥

JSON \n

const split = require('split2')
process.stdin.pipe(split(JSON.parse))
  .on('data', (obj) => {
    console.log(Object.keys(obj))
  })

Pino

Bunyan API

const pino = require('pino')()
pino.info('hello world')
pino.debug({
  big: 'object'
}, 'with message')

Pino

10000 ops — 250ms

One Log Per Request

Ten Logs Per Request

Extreme Mode

10000 logs in 100ms

2x throughput increase

Ten Logs Per Request

Extreme Mode

Trade-off: 4k batching

const pino = require('pino')({
  extreme: true
})
pino.info('hello world')
pino.debug({
  big: 'object'
}, 'with message')

Express

var app = require('express')()
var pino = require('express-pino-logger')()

app.use(pino)

app.get('/', function (req, res) {
  req.log.info('something else')
  res.send('hello world')
})

app.listen(3000)

Hapi

const Hapi = require('hapi')
const server = Hapi.server({
  host: 'localhost',
  port: 3000
})

Hapi

await server.register({
  plugin: require('hapi-pino')
  options: { prettyPrint: true }
})

await server.start()
server.logger().info('log from server instance')

Hapi

server.route({
  method: 'GET', path: '/',
  handler: async function (request, reply) {
    request.log(['a', 'b'], 'Request into hello world')
    request.logger.info('In handler %s', request.path)
    return 'hello world'
  }
})

Restify

var restify = require('restify')
var server = restify.createServer({name: 'app'})

server.use(require('restify-pino-logger')())

server.get('/', function (req, res) {
  req.log.info('something else')
  res.send('hello world')
})

server.listen(3000)

Koa

var Koa = require('koa')
var logger = require('koa-pino-logger')
var app = new Koa()
app.use(logger())
app.use(async (ctx) => {
  ctx.log.info('something else')
  ctx.body = 'hello world'
})
app.listen(3000)

http

var http = require('http')
var server = http.createServer(handle)
var logger = require('pino-http')()
function handle (req, res) {
  logger(req, res)
  req.log.info('something else')
  res.end('hello world')
}
server.listen(3000)

Secret Sauce

Avoid JSON.stringify

Secret Sauce

Date.now()
vs
new Date().toISOString()

Secret Sauce

%FlattenString

module.exports = function flatstr (s) {
  Number(s)
  return s
}

Secret Sauce

fast-safe-stringify

function Circle (val, k, parent) {
  this.val = val
  this.k = k
  this.parent = parent
}
Circle.prototype.toJSON = function toJSON () {
  this.parent[this.k] = this.val
  return '[Circular]'
}

Secret Sauce

quick-format

0x

 $ npm install 0x 

Before

After

HTTP load tester

Trival cross platform installation

Generates 10% more load than alternatives in C

0x + autocannon = 👌

Pino Philosophy

Absolute minimum overhead

Pino Philosophy

Rotate your logs yourself!

Pino Philosophy

Want better readability? Post-process

With pino CLI

pino-colada

https://github.com/lrlna/pino-colada

Pino Philosophy

Transports are separate processes

Demo: ElasticSearch Integration

https://github.com/mcollina/pino-elasticsearch

2016 with Node 6

2017 with Node 6

2017 with Node 8.2+

https://github.com/fastify/fastify

Features Comparison

fastify.get('/', {
  schema: {
    response: {
      200: {
        type: 'object',
        properties: { hello: { type: 'string' } }
      }
    }
  }
}, (req, reply) => {
  reply.send({ hello: 'world' })
})

'use strict'
const fastify = require('fastify')()

fastify.get('/', function (req, reply) {
  reply.send({ hello: 'world' })
})

fastify.listen(3000)

Serialization

fast-json-stringify

• schema-based JSON rendering
• generates code based on the schema
• new Function(), but it is safe

require('http').createServer(handle).listen(3000)

var stringify = require('fast-json-stringify')({
  type: 'object',
  properties: { hello: { type: 'string' } }
})

function handle (req, res) {
  res.setHeader('Content-Type', 'application/json')
  res.end(stringify({ hello: 'world' }))
}

Adding an HTTP router

• https://github.com/delvedor/find-my-way
• avoid closure allocation
• built on a radix-tree
• safe

routing

This presentation

• https://mcollina.github.io/the-cost-of-logging
• https://github.com/mcollina/the-cost-of-logging

http://github.com/mcollina

Thanks!

We are hiring JavaScript developers

matteo.collina@nearform.com

@matteocollina

www.nearform.com