Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add timed sections #485

Open
wants to merge 5 commits into
base: master
Choose a base branch
from
Open

Add timed sections #485

wants to merge 5 commits into from

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