'log.child(..., true)' support for 10x faster with 'simple' field additions

.gitignore

@@ -1,3 +1,4 @@
 /tmp
 /npm-debug.log
 /node_modules
+*.log

CHANGES.md

@@ -2,6 +2,12 @@
 
 ## bunyan 0.3.0 (not yet released)
 
+- `log.child(options[, simple])` Added `simple` boolean arg. Set `true` to
+  assert that options only add fields (no config changes). Results in a 10x
+  speed increase in child creation. See "tools/timechild.js". On my Mac, 
+  "fast child" creation takes about 0.001ms. IOW, if your app is dishing
+  10,000 req/s, then creating a log child for each request will take
+  about 1% of the request time.
 - `log.clone` -> `log.child` to better reflect the relationship: streams and
   serializers are inherited. Streams can't be removed as part of the child
   creation. The child doesn't own the parent's streams (so can't close them).

README.md

@@ -73,7 +73,7 @@ streams at different levels**.
       ]
     });
 
-A **`log.clone(...)`** is provided to specialize a logger for a sub-component.
+A **`log.child(...)`** is provided to specialize a logger for a sub-component.
 The following will have log records from "Wuzzle" instances use exactly the
 same config as its parent, plus include the "component" field.
 
@@ -89,11 +89,25 @@ same config as its parent, plus include the "component" field.
       this.log.warn("This wuzzle is woosey.")
     }
     
-    var wuzzle = new Wuzzle({log: log.clone({component: "wuzzle"})});
+    var wuzzle = new Wuzzle({log: log.child({component: "wuzzle"})});
     wuzzle.woos();
     log.info("done with the wuzzle")
 
 
+An example and a hack: The [node-restify](https://github.com/mcavage/node-restify)
+framework integrates bunyan. One feature is that each restify request handler
+includes a `req.log` logger that is a:
+
+    log.child({req_id: <unique request id>}, true)
+
+Apps using restify can then use `req.log` and have all such log records
+include the unique request id (as "req_id"). Handy. *What is that `true`?* It
+is a small bunyan hack by which you can assert that you're just adding
+simple fields to the child logger. This makes `log.child` 10x faster and,
+hence, never a worry for slowing down HTTP request handling. See the
+changelog for node-bunyan 0.3.0 for details.
+
+
 Back to the `log.{trace|debug|...|fatal}(...)` API:
 
     log.info();     // returns a boolean: is the "info" level enabled?

TODO.md

@@ -1,5 +1,3 @@
-- fast clone: basically make it reasonable to clone per HTTP request.
-  Ditch mutability. Add another context (another entry in Log record tuple?)?
 - `log.close` to close streams and shutdown and `this.closed`
 - line/file: possible to get quickly with v8? Yunong asked.
 - what's the API for changing the logger/stream level(s)?
@@ -58,6 +56,8 @@
             }
         }
     Want some way to have file/line only at certain levesl and lazily.
+- get Mark to show me dtrace provider stuff and consider adding for
+  logging, if helpful.
 - add option to "streams" to take the raw object, not serialized.
   It would be a good hook for people with custom needs that Bunyan doesn't
   care about (e.g. log.ly or hook.io or whatever).

lib/bunyan.js

@@ -138,9 +138,14 @@ function resolveLevel(nameOrNum) {
  *    All other keys are log record fields.
  *
  * An alternative *internal* call signature is used for creating a child:
- *    new Logger(<parent logger>, <child options>);
+ *    new Logger(<parent logger>, <child options>[, <child opts are simple>]);
+ *
+ * @param _childSimple (Boolean) An assertion that the given `_childOptions`
+ *    (a) only add fields (no config) and (b) no serialization handling is
+ *    required for them. IOW, this is a fast path for frequent child
+ *    creation.
  */
-function Logger(options, _childOptions) {
+function Logger(options, _childOptions, _childSimple) {
   xxx('Logger start:', options)
   if (! this instanceof Logger) {
     return new Logger(options, _childOptions);
@@ -154,12 +159,6 @@ function Logger(options, _childOptions) {
     if (! parent instanceof Logger) {
       throw new TypeError('invalid Logger creation: do not pass a second arg');
     }
-    if (options.level) {
-      throw new TypeError('cannot use "level" option when creating a child');
-    }
-    if (options.stream) {
-      throw new TypeError('cannot use "stream" option when creating a child');
-    }
   }
   if (!options) {
     throw new TypeError('options (object) is required');
@@ -168,16 +167,34 @@ function Logger(options, _childOptions) {
     throw new TypeError('cannot mix "streams" with "stream" or "level" options');
   }
   
+  // Fast path for simple child creation.
+  if (parent && _childSimple) {
+    // Single to stream close handling that this child owns none of its
+    // streams.
+    this._isSimpleChild = true;
+
+    this.level = parent.level;
+    this.streams = parent.streams;
+    this.serializers = parent.serializers;
+    this.fields = parent.fields;
+    var names = Object.keys(options);
+    for (var i = 0; i < names.length; i++) {
+      var name = names[i];
+      this.fields[name] = options[name];
+    }
+    return;
+  }
+
   // Null values.
   var self = this;
   if (parent) {
     this.level = parent.level;
     this.streams = [];
-    parent.streams.forEach(function (s) {
+    for (var i = 0; i < parent.streams.length; i++) {
-      var s = objCopy(s);
+      var s = objCopy(parent.streams[i]);
       s.closeOnExit = false; // Don't own parent stream.
-      self.streams.push(s);
+      this.streams.push(s);
-    });
+    }
     this.serializers = objCopy(parent.serializers);
     this.fields = objCopy(parent.fields);
   } else {
@@ -204,7 +221,7 @@ function Logger(options, _childOptions) {
     if (s.level) {
       s.level = resolveLevel(s.level);
     } else {
-      s.level = level;
+      s.level = INFO;
     }
     if (s.level < self.level) {
       self.level = s.level;
@@ -314,9 +331,13 @@ function Logger(options, _childOptions) {
  *        call.
  *      - The parent's serializers are inherited, though can effectively be
  *        overwritten by using duplicate keys.
+ * @param simple {Boolean} Optional. Set to true to assert that `options`
+ *    (a) only add fields (no config) and (b) no serialization handling is
+ *    required for them. IOW, this is a fast path for frequent child
+ *    creation. See "tools/timechild.js" for numbers.
  */
-Logger.prototype.child = function (options) {
+Logger.prototype.child = function (options, simple) {
-  return new Logger(this, options);
+  return new Logger(this, options || {}, simple);
 }
 
 
@@ -330,6 +351,7 @@ Logger.prototype.child = function (options) {
 //  if (this._closed) {
 //    return;
 //  }
+//  if (!this._isSimpleChild) {
 //    self.streams.forEach(function (s) {
 //      if (s.endOnClose) {
 //        xxx("closing stream s:", s);
@@ -337,6 +359,7 @@ Logger.prototype.child = function (options) {
 //        s.endOnClose = false;
 //      }
 //    });
+//  }
 //  this._closed = true;
 //}
 

tools/timechild.js

@@ -0,0 +1,86 @@
+#!/usr/bin/env node
+/*
+ * Time `log.child(...)`.
+ *
+ * Getting 0.011ms on my Mac. For about 1000 req/s that means that the
+ * `log.child` would be about 1% of the time handling that request.
+ * Could do better. I.e. consider a hackish fast path.
+ *
+ * ...
+ *
+ * Added: `log.fastchild({...}, true)`. Use the `true` to assert that
+ * the given options are just new fields (and no serializers).
+ * Result: Another order of magnitude.
+ */
+
+var ben = require('ben');  // npm install ben
+var Logger = require('../lib/bunyan');
+
+var log = new Logger({
+  service: "svc",
+  streams: [
+    {
+      path: __dirname + "/timechild.log"
+    },
+    {
+      stream: process.stdout
+    }
+  ],
+  serializers: {
+    err: Logger.stdSerializers.err
+  }
+});
+
+console.log("Time `log.child`:");
+
+var ms = ben(1e5, function () {
+  var child = log.child();
+});
+console.log(' - adding no fields:  %dms per iteration', ms);
+
+var ms = ben(1e5, function () {
+  var child = log.child({a:1});
+});
+console.log(' - adding one field:  %dms per iteration', ms);
+
+var ms = ben(1e5, function () {
+  var child = log.child({a:1, b:2});
+});
+console.log(' - adding two fields: %dms per iteration', ms);
+
+function fooSerializer(obj) {
+  return {bar: obj.bar};
+}
+var ms = ben(1e5, function () {
+  var child = log.child({
+    a: 1,
+    serializers: {foo: fooSerializer}
+  });
+});
+console.log(' - adding serializer and one field: %dms per iteration', ms);
+
+var ms = ben(1e5, function () {
+  var child = log.child({
+    a: 1,
+    streams: [{
+      stream: process.stderr
+    }]
+  });
+});
+console.log(' - adding a (stderr) stream and one field: %dms per iteration', ms);
+
+var ms = ben(1e6, function () {
+  var child = log.child({}, true);
+});
+console.log(' - [fast] adding no fields:  %dms per iteration', ms);
+
+var ms = ben(1e6, function () {
+  var child = log.child({a:1}, true);
+});
+console.log(' - [fast] adding one field:  %dms per iteration', ms);
+
+var ms = ben(1e6, function () {
+  var child = log.child({a:1, b:2}, true);
+});
+console.log(' - [fast] adding two fields: %dms per iteration', ms);
+