trentm#401 MkLogEmitter Closure Significantly Hampers Performance

lib/bunyan.js

@@ -943,82 +943,95 @@ Logger.prototype._emit = function (rec, noemit) {
 }
 
 
+/**
+ * Build a record object suitable for emitting from the arguments
+ * provided to the a log emitter.
+ */
+function mkRecord(log, minLevel, args) {
+    var excludeFields, fields, msgArgs;
+    if (args[0] instanceof Error) {
+        // `log.<level>(err, ...)`
+        fields = {
+            // Use this Logger's err serializer, if defined.
+            err: (log.serializers && log.serializers.err
+                ? log.serializers.err(args[0])
+                : Logger.stdSerializers.err(args[0]))
+        };
+        excludeFields = {err: true};
+        if (args.length === 1) {
+            msgArgs = [fields.err.message];
+        } else {
+            msgArgs = args.slice(1);
+        }
+    } else if (typeof (args[0]) !== 'object' && args[0] !== null ||
+               Array.isArray(args[0])) {
+        // `log.<level>(msg, ...)`
+        fields = null;
+        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 = args.slice();
+        msgArgs[0] = util.inspect(msgArgs[0]);
+    } else {  // `log.<level>(fields, msg, ...)`
+        fields = args[0];
+        if (args.length === 1 && fields.err &&
+            fields.err instanceof Error)
+        {
+            msgArgs = [fields.err.message];
+        } else {
+            msgArgs = args.slice(1);
+        }
+    }
+
+    // Build up the record object.
+    var rec = objCopy(log.fields);
+    var level = rec.level = minLevel;
+    var recFields = (fields ? objCopy(fields) : null);
+    if (recFields) {
+        if (log.serializers) {
+            log._applySerializers(recFields, excludeFields);
+        }
+        Object.keys(recFields).forEach(function (k) {
+            rec[k] = recFields[k];
+        });
+    }
+    rec.msg = format.apply(log, msgArgs);
+    if (!rec.time) {
+        rec.time = (new Date());
+    }
+    // Get call source info
+    if (log.src && !rec.src) {
+        rec.src = getCaller3Info()
+    }
+    rec.v = LOG_VERSION;
+
+    return rec;
+};
+
+
+/**
+ * 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;
-
-        function mkRecord(args) {
-            var excludeFields;
-            if (args[0] instanceof Error) {
-                // `log.<level>(err, ...)`
-                fields = {
-                    // Use this Logger's err serializer, if defined.
-                    err: (log.serializers && log.serializers.err
-                        ? log.serializers.err(args[0])
-                        : Logger.stdSerializers.err(args[0]))
-                };
-                excludeFields = {err: true};
-                if (args.length === 1) {
-                    msgArgs = [fields.err.message];
-                } else {
-                    msgArgs = Array.prototype.slice.call(args, 1);
-                }
-            } else if (typeof (args[0]) !== 'object' && args[0] !== null ||
-                       Array.isArray(args[0])) {
-                // `log.<level>(msg, ...)`
-                fields = null;
-                msgArgs = Array.prototype.slice.call(args);
-            } 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[0] = util.inspect(msgArgs[0]);
-            } else {  // `log.<level>(fields, msg, ...)`
-                fields = args[0];
-                if (args.length === 1 && fields.err
-                    && fields.err instanceof Error)
-                {
-                    msgArgs = [fields.err.message];
-                } else {
-                    msgArgs = Array.prototype.slice.call(args, 1);
-                }
-            }
-
-            // Build up the record object.
-            var rec = objCopy(log.fields);
-            var level = rec.level = minLevel;
-            var recFields = (fields ? objCopy(fields) : null);
-            if (recFields) {
-                if (log.serializers) {
-                    log._applySerializers(recFields, excludeFields);
-                }
-                Object.keys(recFields).forEach(function (k) {
-                    rec[k] = recFields[k];
-                });
-            }
-            rec.msg = format.apply(log, msgArgs);
-            if (!rec.time) {
-                rec.time = (new Date());
-            }
-            // Get call source info
-            if (log.src && !rec.src) {
-                rec.src = getCaller3Info()
-            }
-            rec.v = LOG_VERSION;
-
-            return rec;
-        };
-
-        var fields = null;
-        var msgArgs = arguments;
         var str = null;
         var rec = null;
-        if (! this._emit) {
+
+        if (!this._emit) {
             /*
              * Show this invalid Bunyan usage warning *once*.
              *
@@ -1036,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 {
-            rec = mkRecord(msgArgs);
+        }
+
+        var msgArgs = new Array(arguments.length);
+        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 ||
-                    (rec && log._emit(rec, true)) ||
-                    log._emit(mkRecord(msgArgs), true) ];
-        });
+
+        if (probes) {
+            probes[minLevel].fire(mkProbeArgs, str, log, minLevel, msgArgs);
+        }
     }
 }
 

package.json

@@ -20,7 +20,7 @@
   "// mv": "required for RotatingFileStream",
   "// moment": "required for local time with CLI",
   "optionalDependencies": {
-    "dtrace-provider": "~0.6",
+    "dtrace-provider": "http://codymello.com/dtrace-provider-0.6.0.tgz",
     "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);