bunyanとwinstonロガーのパフォーマンス比較

npmに公開されているロギングライブラリの有名所、bunyanとwinstonをパフォーマンスの観点から比較してみたところ、**bunyanの方が優れている（イベントループのブロッキングが少ない）**ことが判明しました。

目次

• bunyanとwinstonロガーのパフォーマンス比較
• 前提
• 検証コード
• 実行結果
• 結論
• TIP
• bunyanのログフォーマットを非JSONに

前提

• Ubuntu 16.04 LTS
• node v12.16.1
• bunyan v1.8.12
• winston v3.2.1

検証コード

以下は検証コードです。

bunyan-vs-winston.js

const blocked = require("blocked-at");
// EventLoopブロッキング検出用:
blocked((time, stack) => {
  console.log(`Blocked for ${time}ms, operation started here:`, stack)
}, {
  // 1ミリ秒以上のブロッキングを検出:
  threshold: 1,
});

const LOGLEVEL= 'info';

//****************************************************************
//
// bunyan
// 
//****************************************************************
console.log("*** bunyan logging start ...");
// bunyanロガー生成
const bunyan = require("bunyan");
const bunyanLogger = bunyan.createLogger({
  name: 'app',
  streams: [
    // ファイル出力設定:
    {
      level: LOGLEVEL,
      type: 'rotating-file',
      path: './bunyan.log', // log ERROR and above to a file
      // period: '1d', // daily rotation
      // count: 1, // keep 3 back copies
    },
    // // 標準出力設定:
    // {
    //   level: 'info',
    //   stream: process.stdout // log INFO and above to stdout
    // },
  ],
});

// ログ出力
let interval = 0;
setTimeout(() => {
  bunyanLogger.info("bunyan log");
}, interval);

interval += 1000;
setTimeout(() => {
  bunyanLogger.info("bunyan log");
}, interval);

interval += 1000;
setTimeout(() => {
  bunyanLogger.info("bunyan log");
}, interval);

//****************************************************************
//
// winston
// 
//****************************************************************
console.log("*** winston logging start ...");
// winstonロガー生成
const winston = require("winston");
const winstonLogger = winston.createLogger({
  level: LOGLEVEL,
  format: winston.format.json(),
  transports: [
    new winston.transports.File({ filename: 'winston.log' }),
    // new winston.transports.Console({
    //   format: winston.format.simple(),
    // }),
  ],
});

// ログ出力
interval += 1000;
setTimeout(() => {
  winstonLogger.info("winston log");
}, interval);

interval += 1000;
setTimeout(() => {
  winstonLogger.info("winston log");
}, interval);

interval += 1000;
setTimeout(() => {
  winstonLogger.info("winston log");
}, interval);

bunyan、winstonともに3回づつログをファイルへ出力しています。

実行結果

実行結果はこのようになります:

$ node bunyan-vs-winston.js

*** bunyan logging start ...
*** winston logging start ...
Blocked for 2.5537729988098143ms, operation started here: [
  '    at initAsyncResource (internal/timers.js:153:5)',...
]
Blocked for 1.2255339984893798ms, operation started here: [
  '    at initAsyncResource (internal/timers.js:153:5)',...
]
Blocked for 2.749863000869751ms, operation started here: [
  '    at initAsyncResource (internal/timers.js:153:5)',...
]

標準出力を見て分かる通り、bunyanのロギング処理では1ms以上のブロッキングが検出されなかった一方で、winstonの方では1ms以上のブロッキングを検出しました！ログの出力ごときの処理で1ms以上のブロッキングはリソースが惜しい。。。(ちなみにLOGLEVELをerrorにも設定してみましたが、やはりwinstonの方では1ms以上のブロッキングを検出しました。)

結論

アプリケーション開発ではログ出力を至る所に仕込むことが多いと思いますが、コード中にログ出力が多い場合はパフォーマンスを考慮してbunyan を使う方が良いかもしれません。 (関連: bunyan並みの高パフォーマンスで非JSONなログ出力をお求めならsimple-node-loggerもオススメです。)

TIP

bunyanのログフォーマットを非JSONに

bunyanは基本的にログをJSONフォーマットで出力します:

$ node app.js

{"name":"app","hostname":"user","pid":21737,"level":30,"msg":"hello world!","time":"2020-04-24T00:48:46.490Z","v":0}
...

bunyanで非JSONなシンプルなログを表示したい場合は以下のようにbunyanのCLIツールを使います:

$ node app.js | ./node_modules/bunyan/bin/bunyan -o short

00:46:36.163Z  INFO app: hello world!
...

以上です。