diff --git a/lib/bunyan.js b/lib/bunyan.js index 0817054e..15b83b41 100644 --- a/lib/bunyan.js +++ b/lib/bunyan.js @@ -943,6 +943,84 @@ 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.(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.(msg, ...)` + fields = null; + msgArgs = args.slice(); + } else if (Buffer.isBuffer(args[0])) { // `log.(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.(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. @@ -950,75 +1028,10 @@ Logger.prototype._emit = function (rec, noemit) { function mkLogEmitter(minLevel) { return function () { var log = this; - - function mkRecord(args) { - var excludeFields; - if (args[0] instanceof Error) { - // `log.(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.(msg, ...)` - fields = null; - msgArgs = Array.prototype.slice.call(args); - } else if (Buffer.isBuffer(args[0])) { // `log.(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.(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.()` 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); + } } } diff --git a/package.json b/package.json index a0963c9a..6342326d 100644 --- a/package.json +++ b/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" diff --git a/test/dtrace.test.js b/test/dtrace.test.js index b220a452..e4943b75 100644 --- a/test/dtrace.test.js +++ b/test/dtrace.test.js @@ -115,7 +115,7 @@ test('bunyan -p', function (t) { setTimeout(function () { p.kill(); bunyanP.kill(); - }, 3000); + }, 5000); }); diff --git a/tools/timenop.js b/tools/timenop.js new file mode 100755 index 00000000..11cde8db --- /dev/null +++ b/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);