debug-js
Add timed sections
This adds timed sections, similar to console.time() and console.timeEnd().
I understand completely if this isn't something you guys want added. However, it should be a non-breaking change.
If it is something you're interested in, I'll add docs to the readme :)
This works both in the browser and in Node.
Usage:
const debug = require('debug')('foo:bar');
const sec = debug.begin('section 1');
sec.mark('this is a marker');
sec.mark('it, too, shows the delta from the beginning of the section');
sec.end('finally, we can end the section');
// or simply
sec.end();
As you'd expect, .mark() is entirely optional, and the arguments to .mark() and .end() are optional as well.
Arguments passed to .mark() and .end() are separated from the .begin() text with ::, and all formatting parameters are preserved as you'd expect - even in the browser:
The separation with :: is a trivial change, so if you don't like the way it looks or have a better idea on how to introduce the mark/end text to the existing arguments provided by .begin(), let me know and I can whip it up.
Coverage increased (+4.3%) to 77.049% when pulling 8e91e4411ce6282d2979a748db31dee4c269364f on Qix-:timed-sections into 13e1d068e9265b2c9a160ba242a6be200b9811f0 on visionmedia:master.
An alternative/additional syntax could be:
debug.time('some procedure', () => {
// ... some lengthy operation
});
which would be sugar for
var sec = debug.begin('some procedure');
try {
fn();
} finally {
sec.end();
}
Could even support promises if they're available. Thoughts?
EDIT: went ahead and added them - feel free to revert the commit.
Usage:
const result = debug.time('some critical function', () => {
// do work
return 1234;
});
console.log(result); //-> 1234
const result2 = await debug.time('some critical async function', async () => {
// do work
return 54321;
});
console.log(result); //-> 54321
Coverage increased (+3.9%) to 76.617% when pulling d817675bee1ba02eee23b11df093c84a0ad36306 on Qix-:timed-sections into 13e1d068e9265b2c9a160ba242a6be200b9811f0 on visionmedia:master.
Coverage increased (+4.9%) to 77.612% when pulling 0f768525477b94d966e54e398c564db2780e251c on Qix-:timed-sections into 13e1d068e9265b2c9a160ba242a6be200b9811f0 on visionmedia:master.
Coverage increased (+6.4%) to 79.104% when pulling 299d7c4f8b088ca7254376fdcbb0c025799c268e on Qix-:timed-sections into 13e1d068e9265b2c9a160ba242a6be200b9811f0 on visionmedia:master.
Latest commits do the following:
const sec = debug.begin('section');
sec.mark(); // OK
sec.mark(); // OK
sec.end(); // OK
sec.mark(); // no output
sec.end(); // no output
May be reasonable to throw instead of swallow the output? Let me know. cc @TooTallNate
debug.time('some function', sec => {
// work...
sec.mark('some mark');
// more work...
sec.end('some result');
});
Coverage increased (+6.4%) to 79.126% when pulling 58ceaa06a303527de9480e480d992a3f6ee444d7 on Qix-:timed-sections into 13e1d068e9265b2c9a160ba242a6be200b9811f0 on visionmedia:master.
Coverage increased (+6.4%) to 79.126% when pulling 58ceaa06a303527de9480e480d992a3f6ee444d7 on Qix-:timed-sections into 13e1d068e9265b2c9a160ba242a6be200b9811f0 on visionmedia:master.
@Qix- Very interesting! I did something similar (though a lot more basic) using a custom formatter. That said, my initial question is if this is something that could live as a separate module like my debug-time thing.
The mechanics rely heavily on the formatter and the indirection of the main debug function to be efficient. I don't know if you could do that without a complete fork.
Coverage increased (+5.6%) to 78.302% when pulling e179414b5782eb20943f3dcb6fe2c796f56f84ce on Qix-:timed-sections into 13e1d068e9265b2c9a160ba242a6be200b9811f0 on visionmedia:master.
Coverage increased (+4.1%) to 76.852% when pulling fa073de129767968fc512649aacba6fb0235ae89 on Qix-:timed-sections into 13e1d068e9265b2c9a160ba242a6be200b9811f0 on visionmedia:master.
Coverage increased (+4.5%) to 77.209% when pulling 781595231a1973e566d04dab0d4bd7e51fa4d527 on Qix-:timed-sections into 13e1d068e9265b2c9a160ba242a6be200b9811f0 on visionmedia:master.
Coverage increased (+4.5%) to 77.209% when pulling 781595231a1973e566d04dab0d4bd7e51fa4d527 on Qix-:timed-sections into 13e1d068e9265b2c9a160ba242a6be200b9811f0 on visionmedia:master.
Coverage increased (+4.5%) to 77.209% when pulling 781595231a1973e566d04dab0d4bd7e51fa4d527 on Qix-:timed-sections into 13e1d068e9265b2c9a160ba242a6be200b9811f0 on visionmedia:master.
Let's get this merged @Qix-.
Needs Readme docs and there appears to be a bug where the marked sections fall back to a regular debug() call when stdout is not a TTY (server logs, etc.) that needs to be fixed first as well.
