From 8e91e4411ce6282d2979a748db31dee4c269364f Mon Sep 17 00:00:00 2001 From: Josh Junon Date: Wed, 9 Aug 2017 01:50:08 -0700 Subject: [PATCH 1/5] 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; + }); + }); + }); }); From 299d7c4f8b088ca7254376fdcbb0c025799c268e Mon Sep 17 00:00:00 2001 From: Josh Junon Date: Wed, 9 Aug 2017 05:09:05 -0700 Subject: [PATCH 2/5] add timed functions --- src/debug.js | 31 +++++++++++++++++++++++++ test/debug_spec.js | 57 ++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 88 insertions(+) diff --git a/src/debug.js b/src/debug.js index c1fad6bd..7d3c0d57 100644 --- a/src/debug.js +++ b/src/debug.js @@ -160,6 +160,37 @@ function createDebug(namespace) { return section; }; + debug.time = function () { + var args = [].slice.call(arguments); + if (args.length < 2) { + throw new Error('debug.time() takes at least a debug string and a function'); + } + + var fn = args.pop(); + if (typeof fn !== 'function') { + throw new Error('the last argument to debug.time() must be a function'); + } + + var isPromise = false; + var section = debug.begin.apply(debug, args); + try { + var result = fn(); + + if (typeof Promise === 'function' && result instanceof Promise) { // eslint-disable-line no-undef + isPromise = true; + result.then(function () { + section.end(); + }); + } + + return result; + } finally { + if (!isPromise) { + section.end(); + } + } + }; + // env-specific initialization logic for debug instances if ('function' === typeof exports.init) { exports.init(debug); diff --git a/test/debug_spec.js b/test/debug_spec.js index 52b1177f..5608b983 100644 --- a/test/debug_spec.js +++ b/test/debug_spec.js @@ -82,6 +82,63 @@ describe('debug', function () { expect(log.log).to.have.been.calledThrice; }); + + it('times a critical function', function () { + log.log = sinon.spy(); + + var result = log.time('a critical function', function () { + log('hello from inside'); + return 1234; + }); + + expect(result).to.equal(1234); + expect(log.log).to.have.been.calledThrice; + }); + + if (typeof Promise !== 'undefined') { + it('times a critical asynchronous function', function (cb) { + log.log = sinon.spy(); + + log.time('a critical function', function () { + return new Promise(function (resolve) { + log('hello from the inside'); + resolve(1234); + }); + }).then(function (result) { + expect(result).to.equal(1234); + expect(log.log).to.have.been.calledThrice; + cb(); + }).catch(cb); + }); + } + + it('should throw if there aren\'t enough arguments', function () { + log.log = sinon.stub(); + + expect(function () { + log.time(); + }).to.throw('debug.time() takes at least a debug string and a function'); + + expect(function () { + log.time('hello'); + }).to.throw('debug.time() takes at least a debug string and a function'); + + expect(function () { + log.time(function () {}); + }).to.throw('debug.time() takes at least a debug string and a function'); + }); + + it('should throw if last argument isn\'t a function', function () { + log.log = sinon.stub(); + + expect(function () { + log.time('hello', 1234); + }).to.throw('the last argument to debug.time() must be a function'); + + expect(function () { + log.time('hello', function () {}, 1235); + }).to.throw('the last argument to debug.time() must be a function'); + }); }); }); }); From 5a5d7d9e7b1851519ca3d296158e1fb06a9853f6 Mon Sep 17 00:00:00 2001 From: Josh Junon Date: Wed, 9 Aug 2017 06:04:54 -0700 Subject: [PATCH 3/5] force end() to be final allowable call --- src/debug.js | 11 ++++++++++- 1 file changed, 10 insertions(+), 1 deletion(-) diff --git a/src/debug.js b/src/debug.js index 7d3c0d57..89321df3 100644 --- a/src/debug.js +++ b/src/debug.js @@ -130,8 +130,13 @@ function createDebug(namespace) { // that float must be the delta time in milliseconds. var args = arguments; var beginTime = exports.hrtime(); + var ended = false; var mark = function (title, extraArgs) { + if (ended) { + return; + } + section.title = title; section.deltaTime = exports.hrtime(beginTime); if (extraArgs.length) { @@ -147,7 +152,11 @@ function createDebug(namespace) { var section = { title: '[begin]', end: function () { - return mark('[end]', arguments); + try { + return mark('[end]', arguments); + } finally { + ended = true; + } }, mark: function () { return mark('[mark]', arguments); From 58ceaa06a303527de9480e480d992a3f6ee444d7 Mon Sep 17 00:00:00 2001 From: Josh Junon Date: Wed, 9 Aug 2017 06:05:04 -0700 Subject: [PATCH 4/5] pass section to timed function --- src/debug.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/debug.js b/src/debug.js index 89321df3..2ff93dcf 100644 --- a/src/debug.js +++ b/src/debug.js @@ -183,7 +183,7 @@ function createDebug(namespace) { var isPromise = false; var section = debug.begin.apply(debug, args); try { - var result = fn(); + var result = fn(section); if (typeof Promise === 'function' && result instanceof Promise) { // eslint-disable-line no-undef isPromise = true; From 781595231a1973e566d04dab0d4bd7e51fa4d527 Mon Sep 17 00:00:00 2001 From: Josh Junon Date: Sat, 12 Aug 2017 18:33:07 -0700 Subject: [PATCH 5/5] fix multi-arg and format handling --- src/debug.js | 77 ++++++++++++++++++++++++++++++++++------------------ 1 file changed, 51 insertions(+), 26 deletions(-) diff --git a/src/debug.js b/src/debug.js index 2ff93dcf..10f0f507 100644 --- a/src/debug.js +++ b/src/debug.js @@ -30,7 +30,15 @@ exports.skips = []; * Valid key names are a single, lower or upper-case letter, i.e. "n" and "N". */ -exports.formatters = {}; +exports.formatters = { + s: String, + i: function (v) { + v = Number(v); + return v - (v % 1); + }, + d: Number, + f: Number +}; /** * Select a color. @@ -50,6 +58,39 @@ function selectColor(namespace) { return exports.colors[Math.abs(hash) % exports.colors.length]; } +/** + * Formats a sequence of arguments. + * @api private + */ + +function formatInlineArgs(dbg, args) { + args[0] = exports.coerce(args[0]); + + if ('string' !== typeof args[0]) { + // anything else let's inspect with %O + args.unshift('%O'); + } + + var index = 0; + args[0] = args[0].replace(/%([a-zA-Z%])/g, function(match, format) { + // if we encounter an escaped % then don't increase the array index + if (match === '%%') return match; + index++; + var formatter = exports.formatters[format]; + if ('function' === typeof formatter) { + var val = args[index]; + match = formatter.call(dbg, val); + + // now we need to remove `args[index]` since it's inlined in the `format` + args.splice(index, 1); + index--; + } + return match; + }); + + return args; +} + /** * Create a debugger with the given `namespace`. * @@ -82,30 +123,8 @@ function createDebug(namespace) { args[i] = rawArgs[i]; } - args[0] = exports.coerce(args[0]); - - if ('string' !== typeof args[0]) { - // anything else let's inspect with %O - args.unshift('%O'); - } - // apply any `formatters` transformations - var index = 0; - args[0] = args[0].replace(/%([a-zA-Z%])/g, function(match, format) { - // if we encounter an escaped % then don't increase the array index - if (match === '%%') return match; - index++; - var formatter = exports.formatters[format]; - if ('function' === typeof formatter) { - var val = args[index]; - match = formatter.call(self, val); - - // now we need to remove `args[index]` since it's inlined in the `format` - args.splice(index, 1); - index--; - } - return match; - }); + formatInlineArgs(self, args); // apply env-specific formatting (colors, etc.) exports.formatArgs.call(self, args, section); @@ -140,8 +159,14 @@ function createDebug(namespace) { 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); + var leftArgs = formatInlineArgs(debug, [].slice.call(args)); + var newArgs; + if (extraArgs.length > 0) { + var rightArgs = formatInlineArgs(debug, [].slice.call(extraArgs)); + newArgs = leftArgs.concat(['::']).concat(rightArgs) + } else { + newArgs = leftArgs; + } debugHandle(newArgs, section); } else { debugHandle(args, section);