Permalink
Browse files

trentm/node-bunyan#401 mkLogEmitter closures unnecessary for disabled…

… log levels and have perf impact
  • Loading branch information...
1 parent e4b33d8 commit 3cde7bcb3b0f9e037566634f3bd813e6be8590d7 @melloc melloc committed Oct 6, 2016
Showing with 128 additions and 81 deletions.
  1. +5 −0 CHANGES.md
  2. +1 −1 bin/bunyan
  3. +93 −77 lib/bunyan.js
  4. +2 −2 package.json
  5. +1 −1 test/dtrace.test.js
  6. +26 −0 tools/timenop.js
View
@@ -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.
View
@@ -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');
View
@@ -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,81 +945,93 @@ 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' || 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 (fields && 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' ||
- 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 (fields && 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*.
*
@@ -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 {
- 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);
+ }
}
}
View
@@ -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"
View
@@ -115,7 +115,7 @@ test('bunyan -p', function (t) {
setTimeout(function () {
p.kill();
bunyanP.kill();
- }, 3000);
+ }, 5000);
});
View
@@ -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);

0 comments on commit 3cde7bc

Please sign in to comment.