From 8e91e4411ce6282d2979a748db31dee4c269364f Mon Sep 17 00:00:00 2001 From: Josh Junon Date: Wed, 9 Aug 2017 01:50:08 -0700 Subject: [PATCH] add timed sections --- src/browser.js | 37 ++++++++++++++++++++++++++++++---- src/debug.js | 49 +++++++++++++++++++++++++++++++++++++++++----- src/node.js | 29 ++++++++++++++++++++++++--- test/debug_spec.js | 20 +++++++++++++++++++ 4 files changed, 123 insertions(+), 12 deletions(-) diff --git a/src/browser.js b/src/browser.js index 879aaa79..d39a77aa 100644 --- a/src/browser.js +++ b/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. */ diff --git a/src/debug.js b/src/debug.js index 77e6384a..c1fad6bd 100644 --- a/src/debug.js +++ b/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); diff --git a/src/node.js b/src/node.js index b85ec7e3..8e363e67 100644 --- a/src/node.js +++ b/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. */ diff --git a/test/debug_spec.js b/test/debug_spec.js index 142fbe79..52b1177f 100644 --- a/test/debug_spec.js +++ b/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; + }); + }); + }); });