add timed sections

Author: Qix-

src/browser.js

@@ -10,6 +10,7 @@ exports.formatArgs = formatArgs;
 exports.save = save;
 exports.load = load;
 exports.useColors = useColors;
+exports.hrtime = hrtimeInit();
 exports.storage = 'undefined' != typeof chrome
                && 'undefined' != typeof chrome.storage
                   ? chrome.storage.local
@@ -80,20 +81,28 @@ exports.formatters.j = function(v) {
  * @api public
  */
 
-function formatArgs(args) {
+function formatArgs(args, section) {
   var useColors = this.useColors;
 
   args[0] = (useColors ? '%c' : '')
     + this.namespace
     + (useColors ? ' %c' : ' ')
+    + (section ? (section.title + (useColors ? ' %c' : ' ')) : '')
     + args[0]
     + (useColors ? '%c ' : ' ')
-    + '+' + exports.humanize(this.diff);
+    + '+' + exports.humanize(this.diff)
+    + (section && section.complete ? ('%c (delta ' + (useColors ? '%c+' : '+') + exports.humanize(section.deltaTime) + (useColors ? '%c)' : ')')) : '');
 
   if (!useColors) return;
 
   var c = 'color: ' + this.color;
-  args.splice(1, 0, c, 'color: inherit')
+  var inherit = 'color: inherit';
+
+  if (section) {
+    args.splice(1, 0, c, inherit + '; font-weight: bold', 'font-weight: normal');
+  } else {
+    args.splice(1, 0, c, inherit);
+  }
 
   // the final "%c" is somewhat tricky, because there could be other
   // arguments passed either before or after the %c, so we need to
@@ -110,7 +119,11 @@ function formatArgs(args) {
     }
   });
 
-  args.splice(lastC, 0, c);
+  if (section && section.complete) {
+    args.splice(lastC - 2, 0, c, inherit, c, inherit);
+  } else {
+    args.splice(lastC, 0, c);
+  }
 }
 
 /**
@@ -166,6 +179,22 @@ function load() {
   return r;
 }
 
+/**
+ * Browser implementation of hrtime().
+ *
+ * Follows the spec outlined in debug.begin() (see debug.js).
+ *
+ * If the browser has support for `window.performance.now()`,
+ * then it is used. Otherwise, it falls back to `Date.now()`.
+ */
+function hrtimeInit() {
+  var nowfn = window && window.performance && window.performance.now ? window.performance.now.bind(window.performance) : Date.now;
+  return function (prev) {
+    var now = nowfn();
+    return prev ? (now - prev) : now;
+  };
+}
+
 /**
  * Enable namespaces listed in `localStorage.debug` initially.
  */

src/debug.js

@@ -21,7 +21,6 @@ exports.instances = [];
 /**
  * The currently active debug mode names, and names to skip.
  */
-
 exports.names = [];
 exports.skips = [];
 
@@ -63,7 +62,7 @@ function createDebug(namespace) {
 
   var prevTime;
 
-  function debug() {
+  function debugHandle(rawArgs, section) {
     // disabled?
     if (!debug.enabled) return;
 
@@ -78,9 +77,9 @@ function createDebug(namespace) {
     prevTime = curr;
 
     // turn the `arguments` into a proper Array
-    var args = new Array(arguments.length);
+    var args = new Array(rawArgs.length);
     for (var i = 0; i < args.length; i++) {
-      args[i] = arguments[i];
+      args[i] = rawArgs[i];
     }
 
     args[0] = exports.coerce(args[0]);
@@ -109,18 +108,58 @@ function createDebug(namespace) {
     });
 
     // apply env-specific formatting (colors, etc.)
-    exports.formatArgs.call(self, args);
+    exports.formatArgs.call(self, args, section);
 
     var logFn = debug.log || exports.log || console.log.bind(console);
     logFn.apply(self, args);
   }
 
+  function debug() {
+    debugHandle(arguments);
+  }
+
   debug.namespace = namespace;
   debug.enabled = exports.enabled(namespace);
   debug.useColors = exports.useColors();
   debug.color = selectColor(namespace);
   debug.destroy = destroy;
 
+  debug.begin = function () {
+    // hrtime() can return whatever it wants with no arguments;
+    // however, it must return a float when called with a second parameter;
+    // that float must be the delta time in milliseconds.
+    var args = arguments;
+    var beginTime = exports.hrtime();
+
+    var mark = function (title, extraArgs) {
+      section.title = title;
+      section.deltaTime = exports.hrtime(beginTime);
+      if (extraArgs.length) {
+        var newArgParams = [].slice.call(args, 1).concat([].slice.call(extraArgs, 1))
+        var newArgs = [(args[0] ? args[0] + ' :: ' : '') + (extraArgs[0] || '')].concat(newArgParams);
+        debugHandle(newArgs, section);
+      } else {
+        debugHandle(args, section);
+      }
+      return section;
+    }
+
+    var section = {
+      title: '[begin]',
+      end: function () {
+        return mark('[end]', arguments);
+      },
+      mark: function () {
+        return mark('[mark]', arguments);
+      }
+    };
+
+    debugHandle(args, section);
+    section.complete = true;
+
+    return section;
+  };
+
   // env-specific initialization logic for debug instances
   if ('function' === typeof exports.init) {
     exports.init(debug);

src/node.js

@@ -18,6 +18,7 @@ exports.formatArgs = formatArgs;
 exports.save = save;
 exports.load = load;
 exports.useColors = useColors;
+exports.hrtime = hrtime;
 
 /**
  * Colors.
@@ -101,17 +102,22 @@ exports.formatters.O = function(v) {
  * @api public
  */
 
-function formatArgs(args) {
+function formatArgs(args, section) {
   var name = this.namespace;
   var useColors = this.useColors;
 
   if (useColors) {
     var c = this.color;
     var colorCode = '\u001b[3' + (c < 8 ? c : '8;5;' + c);
-    var prefix = '  ' + colorCode + ';1m' + name + ' ' + '\u001b[0m';
+    var prefix = '  ' + colorCode + ';1m' + name + '\u001b[0m ';
+    var sectionPrefix = section ? ('\u001b[1m' + section.title + '\u001b[0m ') : '';
 
-    args[0] = prefix + args[0].split('\n').join('\n' + prefix);
+    args[0] = prefix + sectionPrefix + args[0].split('\n').join('\n' + prefix);
     args.push(colorCode + 'm+' + exports.humanize(this.diff) + '\u001b[0m');
+
+    if (section && section.complete) {
+      args.push('(delta ' + colorCode + 'm+' + exports.humanize(section.deltaTime) + '\u001b[0m)');
+    }
   } else {
     args[0] = new Date().toISOString()
       + ' ' + name + ' ' + args[0];
@@ -170,6 +176,23 @@ function init (debug) {
   }
 }
 
+/**
+ * Wrapper around Node's process.hrtime().
+ *
+ * As per the spec defined by debug.begin() (see debug.js),
+ * this function returns normally when there is no argument,
+ * but returns a delta float in the event that there is.
+ */
+
+function hrtime(prev) {
+  if (prev) {
+    var delta = process.hrtime(prev);
+    return (delta[0] * 1000) + (delta[1] / 1e6);
+  }
+
+  return process.hrtime();
+}
+
 /**
  * Enable namespaces listed in `process.env.DEBUG` initially.
  */

test/debug_spec.js

@@ -64,4 +64,24 @@ describe('debug', function () {
     });
   });
 
+  describe('timed sections', function () {
+    var log;
+
+    beforeEach(function () {
+      debug.enable('test');
+      log = debug('test');
+    });
+
+    context('with log function', function () {
+      it('times a critical section', function () {
+        log.log = sinon.spy();
+
+        var section = log.begin('a critical section');
+        log('something inside the section');
+        section.end();
+
+        expect(log.log).to.have.been.calledThrice;
+      });
+    });
+  });
 });