Skip to content

Conversation

Qix-
Copy link
Member

@Qix- Qix- commented Aug 9, 2017

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();

screen shot 2017-08-09 at 2 18 25 am

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:

screen shot 2017-08-09 at 2 19 27 am

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.

@coveralls
Copy link

coveralls commented Aug 9, 2017

Coverage Status

Coverage increased (+4.3%) to 77.049% when pulling 8e91e44 on Qix-:timed-sections into 13e1d06 on visionmedia:master.

@Qix-
Copy link
Member Author

Qix- commented Aug 9, 2017

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

@coveralls
Copy link

coveralls commented Aug 9, 2017

Coverage Status

Coverage increased (+3.9%) to 76.617% when pulling d817675 on Qix-:timed-sections into 13e1d06 on visionmedia:master.

@coveralls
Copy link

coveralls commented Aug 9, 2017

Coverage Status

Coverage increased (+4.9%) to 77.612% when pulling 0f76852 on Qix-:timed-sections into 13e1d06 on visionmedia:master.

@coveralls
Copy link

coveralls commented Aug 9, 2017

Coverage Status

Coverage increased (+6.4%) to 79.104% when pulling 299d7c4 on Qix-:timed-sections into 13e1d06 on visionmedia:master.

@Qix-
Copy link
Member Author

Qix- commented Aug 9, 2017

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');
});

@coveralls
Copy link

coveralls commented Aug 9, 2017

Coverage Status

Coverage increased (+6.4%) to 79.126% when pulling 58ceaa0 on Qix-:timed-sections into 13e1d06 on visionmedia:master.

1 similar comment
@coveralls
Copy link

Coverage Status

Coverage increased (+6.4%) to 79.126% when pulling 58ceaa0 on Qix-:timed-sections into 13e1d06 on visionmedia:master.

@TooTallNate
Copy link
Contributor

@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.

@Qix-
Copy link
Member Author

Qix- commented Aug 9, 2017

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.

@coveralls
Copy link

coveralls commented Aug 13, 2017

Coverage Status

Coverage increased (+5.6%) to 78.302% when pulling e179414 on Qix-:timed-sections into 13e1d06 on visionmedia:master.

@coveralls
Copy link

coveralls commented Aug 13, 2017

Coverage Status

Coverage increased (+4.1%) to 76.852% when pulling fa073de on Qix-:timed-sections into 13e1d06 on visionmedia:master.

@coveralls
Copy link

Coverage Status

Coverage increased (+4.5%) to 77.209% when pulling 7815952 on Qix-:timed-sections into 13e1d06 on visionmedia:master.

2 similar comments
@coveralls
Copy link

Coverage Status

Coverage increased (+4.5%) to 77.209% when pulling 7815952 on Qix-:timed-sections into 13e1d06 on visionmedia:master.

@coveralls
Copy link

Coverage Status

Coverage increased (+4.5%) to 77.209% when pulling 7815952 on Qix-:timed-sections into 13e1d06 on visionmedia:master.

exports.formatters = {};
exports.formatters = {
s: String,
i: function (v) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

parseInt(v, 10)?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

const o = { valueOf: () => 1234 };

parseInt(o, 10); //-> NaN
Number(o); //-> 1234

@TooTallNate
Copy link
Contributor

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.

@DiegoRBaquero
Copy link
Contributor

This is a really nice feature. @Qix-

@Qix- Qix- self-assigned this Jun 20, 2018
@Qix- Qix- added feature This proposes or provides a feature or enhancement needs-documentation This issue or change requires additional documentation labels Jun 20, 2018
@Qix- Qix- added the awaiting-response This issue or pull request is awaiting a user's response label Jul 26, 2018
@rmwxiong
Copy link

Any plans to get this in @Qix- ?

@Qix- Qix- added this to the 5.x milestone Dec 19, 2018
@Qix- Qix- mentioned this pull request Dec 19, 2018
11 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
awaiting-response This issue or pull request is awaiting a user's response feature This proposes or provides a feature or enhancement needs-documentation This issue or change requires additional documentation
Development

Successfully merging this pull request may close these issues.

5 participants