trentm/node-bunyan#401 mkLogEmitter closures unnecessary for disabled log levels and have perf impact

CHANGES.md

@@ -8,6 +8,11 @@ Known issues:
 ## not yet released
 
 
+## 1.8.5
+
+- [issue #401] Improved performance when using disabled log levels.
+
+
 ## 1.8.4
 
 - [issue #454] Fix `src` usage with node v7.

bin/bunyan

@@ -11,7 +11,7 @@
  * vim: expandtab:ts=4:sw=4
  */
 
-var VERSION = '1.8.4';
+var VERSION = '1.8.5';
 
 var p = console.log;
 var util = require('util');

lib/bunyan.js

@@ -8,7 +8,7 @@
  * vim: expandtab:ts=4:sw=4
  */
 
-var VERSION = '1.8.4';
+var VERSION = '1.8.5';
 
 /*
  * Bunyan log format version. This becomes the 'v' field on all log records.
@@ -945,15 +945,11 @@ Logger.prototype._emit = function (rec, noemit) {
 
 
 /**
- * Build a log emitter function for level minLevel. I.e. this is the
+ * Build a record object suitable for emitting from the arguments
- * creator of `log.info`, `log.error`, etc.
+ * provided to the a log emitter.
  */
-function mkLogEmitter(minLevel) {
+function mkRecord(log, minLevel, args) {
-    return function () {
+    var excludeFields, fields, msgArgs;
-        var log = this;
-
-        function mkRecord(args) {
-            var excludeFields;
     if (args[0] instanceof Error) {
         // `log.<level>(err, ...)`
         fields = {
@@ -966,18 +962,17 @@ function mkLogEmitter(minLevel) {
         if (args.length === 1) {
             msgArgs = [fields.err.message];
         } else {
-                    msgArgs = Array.prototype.slice.call(args, 1);
+            msgArgs = args.slice(1);
         }
-            } else if (typeof (args[0]) !== 'object' ||
+    } else if (typeof (args[0]) !== 'object' || Array.isArray(args[0])) {
-                    Array.isArray(args[0])) {
         // `log.<level>(msg, ...)`
         fields = null;
-                msgArgs = Array.prototype.slice.call(args);
+        msgArgs = args.slice();
     } else if (Buffer.isBuffer(args[0])) {  // `log.<level>(buf, ...)`
         // Almost certainly an error, show `inspect(buf)`. See bunyan
         // issue #35.
         fields = null;
-                msgArgs = Array.prototype.slice.call(args);
+        msgArgs = args.slice();
         msgArgs[0] = util.inspect(msgArgs[0]);
     } else {  // `log.<level>(fields, msg, ...)`
         fields = args[0];
@@ -986,7 +981,7 @@ function mkLogEmitter(minLevel) {
         {
             msgArgs = [fields.err.message];
         } else {
-                    msgArgs = Array.prototype.slice.call(args, 1);
+            msgArgs = args.slice(1);
         }
     }
 
@@ -1015,10 +1010,27 @@ function mkLogEmitter(minLevel) {
     return rec;
 };
 
-        var fields = null;
+
-        var msgArgs = arguments;
+/**
+ * Build an array that dtrace-provider can use to fire a USDT probe. If we've
+ * already built the appropriate string, we use it. Otherwise, build the
+ * record object and stringify it.
+ */
+function mkProbeArgs(str, log, minLevel, msgArgs) {
+    return [ str || log._emit(mkRecord(log, minLevel, msgArgs), true) ];
+}
+
+
+/**
+ * Build a log emitter function for level minLevel. I.e. this is the
+ * creator of `log.info`, `log.error`, etc.
+ */
+function mkLogEmitter(minLevel) {
+    return function () {
+        var log = this;
         var str = null;
         var rec = null;
+
         if (!this._emit) {
             /*
              * Show this invalid Bunyan usage warning *once*.
@@ -1037,17 +1049,21 @@ function mkLogEmitter(minLevel) {
             return;
         } else if (arguments.length === 0) {   // `log.<level>()`
             return (this._level <= minLevel);
-        } else if (this._level > minLevel) {
+        }
-            /* pass through */
+
-        } else {
+        var msgArgs = new Array(arguments.length);
-            rec = mkRecord(msgArgs);
+        for (var i = 0; i < msgArgs.length; ++i) {
+            msgArgs[i] = arguments[i];
+        }
+
+        if (this._level <= minLevel) {
+            rec = mkRecord(log, minLevel, msgArgs);
             str = this._emit(rec);
         }
-        probes && probes[minLevel].fire(function () {
+
-                return [ str ||
+        if (probes) {
-                    (rec && log._emit(rec, true)) ||
+            probes[minLevel].fire(mkProbeArgs, str, log, minLevel, msgArgs);
-                    log._emit(mkRecord(msgArgs), true) ];
+        }
-        });
     }
 }
 

package.json

@@ -1,6 +1,6 @@
 {
   "name": "bunyan",
-  "version": "1.8.4",
+  "version": "1.8.5",
   "description": "a JSON logging library for node.js services",
   "author": "Trent Mick <trentm@gmail.com> (http://trentm.com)",
   "main": "./lib/bunyan.js",
@@ -20,7 +20,7 @@
   "// mv": "required for RotatingFileStream",
   "// moment": "required for local time with CLI",
   "optionalDependencies": {
-    "dtrace-provider": "~0.7",
+    "dtrace-provider": "~0.8",
     "mv": "~2",
     "safe-json-stringify": "~1",
     "moment": "^2.10.6"

test/dtrace.test.js

@@ -115,7 +115,7 @@ test('bunyan -p', function (t) {
     setTimeout(function () {
         p.kill();
         bunyanP.kill();
-    }, 3000);
+    }, 5000);
 });
 
 

tools/timenop.js

@@ -0,0 +1,26 @@
+#!/usr/bin/env node
+/*
+ * Time logging below the current level, which should do very little work.
+ */
+
+console.log('Time log.trace() when log level is "info":');
+
+var ben = require('ben');  // npm install ben
+var bunyan = require('../lib/bunyan');
+
+function Collector() {}
+Collector.prototype.write = function (s) {};
+
+var log = bunyan.createLogger({
+    name: 'timeguard',
+    level: 'info',
+    stream: new Collector()
+});
+
+var i = 0;
+var ms, fields;
+
+ms = ben(1e7, function () {
+    log.trace({ count: i++ }, 'hello');
+});
+console.log(' - log.trace:     %dms per iteration', ms);