From 40777aaf35bd7415b05960062f3b77092aff4b37 Mon Sep 17 00:00:00 2001 From: Trent Mick Date: Sat, 4 Feb 2012 21:42:47 -0800 Subject: [PATCH] 'log.child(..., true)' support for 10x faster with 'simple' field additions --- .gitignore | 1 + CHANGES.md | 6 ++++ README.md | 18 ++++++++-- TODO.md | 4 +-- lib/bunyan.js | 67 ++++++++++++++++++++++++------------ tools/timechild.js | 86 ++++++++++++++++++++++++++++++++++++++++++++++ 6 files changed, 156 insertions(+), 26 deletions(-) create mode 100755 tools/timechild.js diff --git a/.gitignore b/.gitignore index 39a7c5c..f371022 100644 --- a/.gitignore +++ b/.gitignore @@ -1,3 +1,4 @@ /tmp /npm-debug.log /node_modules +*.log diff --git a/CHANGES.md b/CHANGES.md index f6b97d2..bca7b9e 100644 --- a/CHANGES.md +++ b/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). diff --git a/README.md b/README.md index 51dbe3e..95f74d4 100644 --- a/README.md +++ b/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: }, 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? diff --git a/TODO.md b/TODO.md index e0e483c..d511a8d 100644 --- a/TODO.md +++ b/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). diff --git a/lib/bunyan.js b/lib/bunyan.js index e7a680c..a044dd8 100644 --- a/lib/bunyan.js +++ b/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(, ); + * new Logger(, [, ]); + * + * @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) { - var s = objCopy(s); + for (var i = 0; i < parent.streams.length; i++) { + 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) { - return new Logger(this, options); +Logger.prototype.child = function (options, simple) { + return new Logger(this, options || {}, simple); } @@ -330,13 +351,15 @@ Logger.prototype.child = function (options) { // if (this._closed) { // return; // } -// self.streams.forEach(function (s) { -// if (s.endOnClose) { -// xxx("closing stream s:", s); -// s.stream.end(); -// s.endOnClose = false; -// } -// }); +// if (!this._isSimpleChild) { +// self.streams.forEach(function (s) { +// if (s.endOnClose) { +// xxx("closing stream s:", s); +// s.stream.end(); +// s.endOnClose = false; +// } +// }); +// } // this._closed = true; //} diff --git a/tools/timechild.js b/tools/timechild.js new file mode 100755 index 0000000..e704134 --- /dev/null +++ b/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); +