Bunyan's safeCycles is too slow when logging large objects. Fixes #474

CHANGES.md

@@ -8,6 +8,11 @@ Known issues:
 ## not yet released
 
 
+## 1.8.6
+
+- [issue #474] Bunyan's `safeCycles` is too slow when logging large objects.
+
+
 ## 1.8.5
 
 - [issue #401] Improved performance when using disabled log levels.

bin/bunyan

@@ -11,7 +11,7 @@
  * vim: expandtab:ts=4:sw=4
  */
 
-var VERSION = '1.8.5';
+var VERSION = '1.8.6';
 
 var p = console.log;
 var util = require('util');

lib/bunyan.js

@@ -8,7 +8,7 @@
  * vim: expandtab:ts=4:sw=4
  */
 
-var VERSION = '1.8.5';
+var VERSION = '1.8.6';
 
 /*
  * Bunyan log format version. This becomes the 'v' field on all log records.
@@ -155,7 +155,7 @@ if (!format) {
             switch (x) {
                 case '%s': return String(args[i++]);
                 case '%d': return Number(args[i++]);
-                case '%j': return JSON.stringify(args[i++], safeCycles());
+                case '%j': return fastAndSafeJsonStringify(args[i++]);
                 case '%%': return '%';
                 default:
                     return x;
@@ -905,26 +905,10 @@ Logger.prototype._emit = function (rec, noemit) {
         }
     }
 
-    // Stringify the object. Attempt to warn/recover on error.
+    // Stringify the object (creates a warning str on error).
     var str;
     if (noemit || this.haveNonRawStreams) {
-        try {
-            str = JSON.stringify(rec, safeCycles()) + '\n';
-        } catch (e) {
-            if (safeJsonStringify) {
-                str = safeJsonStringify(rec) + '\n';
-            } else {
-                var dedupKey = e.stack.split(/\n/g, 2).join('\n');
-                _warn('bunyan: ERROR: Exception in '
-                    + '`JSON.stringify(rec)`. You can install the '
-                    + '"safe-json-stringify" module to have Bunyan fallback '
-                    + 'to safer stringification. Record:\n'
-                    + _indent(format('%s\n%s', util.inspect(rec), e.stack)),
-                    dedupKey);
-                str = format('(Exception in JSON.stringify(rec): %j. '
-                    + 'See stderr for details.)\n', e.message);
-            }
-        }
+        str = fastAndSafeJsonStringify(rec) + '\n';
     }
 
     if (noemit)
@@ -1168,9 +1152,30 @@ var errSerializer = Logger.stdSerializers.err = function err(err) {
 };
 
 
-// A JSON stringifier that handles cycles safely.
-// Usage: JSON.stringify(obj, safeCycles())
-function safeCycles() {
+// A JSON stringifier that handles cycles safely - tracks seen values in a Set.
+function safeCyclesSet() {
+    var seen = new Set();
+    return function (key, val) {
+        if (!val || typeof (val) !== 'object') {
+            return val;
+        }
+        if (seen.has(val)) {
+            return '[Circular]';
+        }
+        seen.add(val);
+        return val;
+    };
+}
+
+/**
+ * A JSON stringifier that handles cycles safely - tracks seen vals in an Array.
+ *
+ * Note: This approach has performance problems when dealing with large objects,
+ * see trentm/node-bunyan#445, but since this is the only option for node 0.10
+ * and earlier (as Set was introduced in Node 0.12), it's used as a fallback
+ * when Set is not available.
+ */
+function safeCyclesArray() {
     var seen = [];
     return function (key, val) {
         if (!val || typeof (val) !== 'object') {
@@ -1184,6 +1189,47 @@ function safeCycles() {
     };
 }
 
+/**
+ * A JSON stringifier that handles cycles safely.
+ *
+ * Usage: JSON.stringify(obj, safeCycles())
+ *
+ * Choose the best safe cycle function from what is available - see
+ * trentm/node-bunyan#445.
+ */
+var safeCycles = Set ? safeCyclesSet : safeCyclesArray;
+
+/**
+ * A fast JSON.stringify that handles cycles and getter exceptions (when
+ * safeJsonStringify is installed).
+ *
+ * This function attempts to use the regular JSON.stringify for speed, but on
+ * error (e.g. JSON cycle detection exception) it falls back to safe stringify
+ * handlers that can deal with cycles and/or getter exceptions.
+ */
+function fastAndSafeJsonStringify(rec) {
+    try {
+        return JSON.stringify(rec);
+    } catch (ex) {
+        try {
+            return JSON.stringify(rec, safeCycles());
+        } catch (e) {
+            if (safeJsonStringify) {
+                return safeJsonStringify(rec);
+            } else {
+                var dedupKey = e.stack.split(/\n/g, 3).join('\n');
+                _warn('bunyan: ERROR: Exception in '
+                    + '`JSON.stringify(rec)`. You can install the '
+                    + '"safe-json-stringify" module to have Bunyan fallback '
+                    + 'to safer stringification. Record:\n'
+                    + _indent(format('%s\n%s', util.inspect(rec), e.stack)),
+                    dedupKey);
+                return format('(Exception in JSON.stringify(rec): %j. '
+                    + 'See stderr for details.)', e.message);
+            }
+        }
+    }
+}
 
 
 var RotatingFileStream = null;

package.json

@@ -1,6 +1,6 @@
 {
   "name": "bunyan",
-  "version": "1.8.5",
+  "version": "1.8.6",
   "description": "a JSON logging library for node.js services",
   "author": "Trent Mick <trentm@gmail.com> (http://trentm.com)",
   "main": "./lib/bunyan.js",