Merge pull request #80 from stencila/perf

BREAKING CHANGE: Mostly internal performance improvements but given the scale of changes labeling as a breaking change to trigger a major release.

benchmark.js

@@ -0,0 +1,124 @@
+/**
+ * Benchmarks comparing the speed of Logga to other Node.js logging frameworks
+ *
+ * First install the benchmark and logging libraries
+ *
+ * ```sh
+ * npm install --no-save benchmark bole bunyan log4js loglevel pino winston
+ * ```
+ *
+ * Then to rebuild Logga and run the benchmarks,
+ *
+ * ```sh
+ * npm run bench
+ * ```
+ *
+ * All frameworks configured to log errors to `stderr`.
+ * Build Logga if necessary before running benchmarks.
+ * Best run by redireting `stderr` to `/dev/null` e.g.
+ *
+ */
+
+const Benchmark = require('benchmark')
+
+// Import each of the libraries used
+
+const bole = require('bole')
+const bunyan = require('bunyan')
+const log4js = require('log4js')
+const logga = require('.')
+const loglevel = require('loglevel')
+const pino = require('pino')
+const winston = require('winston')
+
+// Instantiate loggers for each library
+
+const boleLogger = bole('bench')
+bole
+  .output({
+    level: 'error',
+    stream: process.stderr,
+  })
+  .setFastTime(true)
+
+const bunyanLogger = bunyan.createLogger({
+  name: 'bench',
+  streams: [
+    {
+      level: 'error',
+      stream: process.stderr,
+    },
+  ],
+})
+
+var log4jsLogger = log4js.getLogger()
+log4jsLogger.level = 'error'
+log4js.configure({
+  appenders: { err: { type: 'stderr' } },
+  categories: { default: { appenders: ['err'], level: 'ERROR' } },
+})
+
+const loggaLogger = logga.getLogger('bench')
+logga.replaceHandlers((entry) => {
+  logga.defaultHandler(entry, { fastTime: true, exitOnError: false })
+})
+
+const loglevelLogger = loglevel.getLogger('bench')
+loglevelLogger.setLevel('error')
+
+const pinoLogger = pino(process.stderr, { name: 'bench' })
+
+const winstonLogger = winston.createLogger({
+  transports: [
+    new winston.transports.Stream({
+      stream: process.stderr,
+    }),
+  ],
+})
+
+// Run the benchmark suites!
+
+// A more precise benchmark for comparing performance
+// across changes in code
+new Benchmark.Suite()
+  .add('logga', {
+    minSamples: 500,
+    fn: function () {
+      loggaLogger.error('derp')
+    },
+  })
+  .on('cycle', function (event) {
+    console.log(String(event.target))
+  })
+  .run()
+
+// For comparison with other libraries
+new Benchmark.Suite()
+  .add('bole', function () {
+    boleLogger.error('derp')
+  })
+  .add('bunyan', function () {
+    bunyanLogger.error('derp')
+  })
+  .add('logga', function () {
+    loggaLogger.error('derp')
+  })
+  .add('log4js', function () {
+    log4jsLogger.error('derp')
+  })
+  .add('loglevel', function () {
+    loglevelLogger.error('derp')
+  })
+  .add('pino', function () {
+    pinoLogger.error('derp')
+  })
+  .add('winston', function () {
+    winstonLogger.error('derp')
+  })
+  .on('cycle', function (event) {
+    console.log(String(event.target))
+  })
+  .on('complete', function () {
+    console.log('Fastest is ' + this.filter('fastest').map('name'))
+  })
+  .run()

example.js

@@ -29,6 +29,6 @@ try {
   const { message, stack } = error
   log.error({
     message: 'Woaaah something bad happened! ' + message,
-    stack
+    stack,
   })
 }

index.d.ts

@@ -0,0 +1,13 @@
+import { LogHandler } from './index'
+
+declare global {
+  namespace NodeJS {
+    interface Global {
+      _logga?: LogHandler[]
+    }
+  }
+
+  interface Window {
+    _logga?: LogHandler[]
+  }
+}

index.test.ts

@@ -1,5 +1,6 @@
 import {
   addHandler,
+  escape,
   getLogger,
   LogData,
   LogLevel,
@@ -9,6 +10,11 @@ import {
   defaultHandler,
 } from './index'
 
+const spyOnWriter = () =>
+  typeof process !== 'undefined'
+    ? jest.spyOn(process.stderr, 'write')
+    : jest.spyOn(console, 'error')
+
 test('logging', () => {
   const TAG = 'tests:logging'
   const log = getLogger(TAG)
@@ -36,23 +42,37 @@ test('logging', () => {
   log.warn('a warning message')
   expect(events[2].level).toBe(LogLevel.warn)
 
-  log.error('an error message')
+  let error = new Error('an error message')
+  log.error(error)
   expect(events[3].level).toBe(LogLevel.error)
   expect(events[3].stack).toMatch(/^Error:/)
   // Second line (first call stack) in stack trace should be this file
   // @ts-ignore
   expect(events[3].stack.split('\n')[1]).toMatch(/\/index\.test\.ts/)
 })
 
+test('escape', () => {
+  expect(escape('"')).toEqual('"')
+  expect(escape('\\')).toEqual('\\\\')
+  expect(escape('/')).toEqual('\\/')
+  expect(escape('\f')).toEqual('\\f')
+  expect(escape('\n')).toEqual('\\n')
+  expect(escape('\r')).toEqual('\\r')
+  expect(escape('\t')).toEqual('\\t')
+})
+
 test('TTY', () => {
   const log = getLogger('tests:tty')
-  replaceHandlers((data) => defaultHandler(data, { exitOnError: false }))
+  replaceHandlers((data) =>
+    defaultHandler(data, { exitOnError: false, showStack: true })
+  )
 
   // Fake that we are using a TTY device
   process.stderr.isTTY = true
   const consoleError = jest.spyOn(console, 'error')
 
-  log.error('an error message')
+  let error = new Error('an error message')
+  log.error(error)
 
   expect(consoleError).toHaveBeenCalledWith(
     expect.stringMatching(/ERROR(.*)?an error message/)
@@ -66,9 +86,10 @@ test('non-TTY', () => {
   // Fake that we are using a non-TTY device
   // @ts-ignore
   process.stderr.isTTY = false
-  const consoleError = jest.spyOn(console, 'error')
+  const consoleError = spyOnWriter()
 
-  log.error('an error message')
+  let error = new Error('an error message')
+  log.error(error)
 
   const json = consoleError.mock.calls[consoleError.mock.calls.length - 1][0]
   const data = JSON.parse(json)
@@ -78,9 +99,21 @@ test('non-TTY', () => {
   expect(data.stack).toBeTruthy()
 })
 
+test('exit on error', () => {
+  const log = getLogger('tests:exit-on-error')
+  replaceHandlers((data) => defaultHandler(data, { exitOnError: true }))
+
+  const mockExit = jest
+    .spyOn(process, 'exit')
+    // @ts-ignore
+    .mockImplementation((code?: number): never => {})
+  log.error('an error message')
+  expect(mockExit).toHaveBeenCalledWith(1)
+})
+
 test('adding and removing handlers', () => {
   const log = getLogger('tests:handlers')
-  const consoleError = jest.spyOn(console, 'error')
+  const consoleError = spyOnWriter()
   const consoleErrorCalls = consoleError.mock.calls.length
   const events: LogData[] = []
 
@@ -178,7 +211,7 @@ test('adding a handler with filter options', () => {
 test('defaultHandler:maxLevel', () => {
   const log = getLogger('logger')
 
-  const consoleError = jest.spyOn(console, 'error')
+  const consoleError = spyOnWriter()
   const callsStart = consoleError.mock.calls.length
 
   log.debug('a debug message')
@@ -199,7 +232,7 @@ test('defaultHandler:maxLevel', () => {
 test('defaultHandler:throttle', async () => {
   const log = getLogger('logger')
 
-  const consoleError = jest.spyOn(console, 'error')
+  const consoleError = spyOnWriter()
   const callsStart = consoleError.mock.calls.length
 
   replaceHandlers((data) =>