Include timing of beforeEach in test duration

[sgilroy]

Description of the Change

As noted in #419 it is sometimes desirable to include the duration of any beforeEach/setup hooks in the duration of tests. This PR adds an option --time-setup which allows this. The --time-setup option is helpful when looking to discover slow tests, where the setup makes up a significant portion of the total duration. Without this option, the user has no visibility into the time being spent in setup. The --time-setup option can be combined with --slow to find tests that exceed a slow threshold.

Alternate Designs

Alternative designs:

1. Include detailed timing about all hooks and allow plugins or reporters to decide what to do with the timing information. The existing duration attribute would not need to be redefined.
2. Add pseudo-tests for timing of before()/after() hooks #3368.

The design implemented in this PR has the advantage of being compatible with existing tooling and the --slow feature. For users who want to opt in to measuring beforeEach hooks, all existing test reporters can display this redefined duration in place of the normal tests-only duration. The alternatives described above could make this feature obsolete, but are significantly larger scope.

Alternative option names:

1. measure-before https://github.com/mochajs/mocha/issues/700
2. include-before-each
3. include-setup-time
4. before-each-timing

I'm open to renaming the option.

Why should this be in core?

Mocha does not expose a mechanism for a plugin to extend or override how the duration of each test is calculated. Detailed timing information is not available for tests.

Benefits

Users are able to detect slow beforeEach hooks and better understand the overall performance of their test suites.

Possible Drawbacks

Increased complexity. Yet another option to document, understand, and maintain.

Applicable issues

Fixes #419 semver-minor

[jsf-clabot]

All committers have signed the CLA.

[coveralls]

Coverage increased (+0.09%) to 91.768% when pulling b438874ed917536692e55f680d75522c7b51e0b2 on TwineHealth:include-before-each into 9e95d36e4b715380cef573014dec852bded3f8e1 on mochajs:master.

[sgilroy]

@kevinburkeshyp @kevinburke Could you please sign the mocha Contributor License Agreement so that your commit can be accepted as part of this PR? Thanks!

[kevinburke]

I believe I have other commits to this project already? Are they not sufficient?

[kevinburke]

I signed as kevinburke / [email protected]. I don't have access to the [email protected] email address used for the first commit, the company is now defunct.

You have my blessing to just cherry pick the commit contents and change the author, a note (originally suggested by Kevin Burke) or something in the commit message would be appreciated!

[szb512]

Make that 2/3 commiters have signed the CLA.

[plroebuck]

For what it's worth, think Mocha should have a stats.timing object that collects durations for all suites, tests, hooks implicitly.

[sgilroy]

I recreated the branch by cherry picking the commit from [email protected], changing the author to [email protected]. Looks like the license/cla check is passing now.

[sgilroy]

@boneskull Capturing timing details on stats sounds desirable, and using a new or modified reporter to then see the complete timing information would potentially address many use cases. However, I think it is important to support the behavior implemented in this PR, and enable a way to actually change the duration of each test, so that existing reporters (and the --slow feature) will include the time from any setup hooks. It is valuable to be compatible with existing reporters, including the one I use in my IDE.

Given that there does not appear to be a plugin API yet for mocha https://github.com/mochajs/mocha/issues/1457, I don't know how I would accomplish this without making a change to set the duration in the core of mocha. Any suggestions for a way to provide existing reporters with duration that includes time from setup hooks?

[sgilroy]

@boneskull I'm looking for some feedback on my response to your concerns so that I know how to proceed. As I stated I'd like to figure out a path to being able to include time for setup/beforeEach hooks in the duration seen by existing reporters and --slow.

Are you suggesting that you will not accept some form of this enhancement into mocha? Or is there some way to rework this to be compatible with the vision for stats.timing suggested by @plroebuck?

Perhaps it would be possible for a reporter to modify duration. Would this be appropriate? Is there a good/supported way to enhance mocha in this way without patching the core?

[boneskull]

@sgilroy Making any built-in reporter report this information is going to be semver-major, and doesn't need to be part of this PR, which would be to just collect these statistics so a) built-in reporters could eventually use them, and b) a custom reporter could use them immediately.

To expose this information, you'll want to do something like this:

1. Create an e.g., appendHookDuration method on Test. This function should be invoked after each Hook has completed execution against its ctx.currentTest property, passing the Hook's duration property. This method should increase the value of some numeric internal property within Test, or use some other data structure. Careful to reset the value if a test needs to be retried.
2. Create a method on Test to retrieve the hook duration (a getter)
3. Tests, of course

To use this information with a reporter, you'd create a listener on the Runner's EVENT_TEST_END event, which receives a Test object as its parameter. You can then get the hook duration(s) by calling your getter. From within this listener, you could add the hook duration(s) to the duration property of your Test. Then output the info as you like.

Please let me know if the above is what you were looking for.

[boneskull]

(See the json reporter for an example of how to collect information about the tests and output it when the run is complete)

[sgilroy]

@boneskull I don't understand why you are asserting that "Making any built-in reporter report this information is going to be semver-major". The modified behavior is only effective if the option (currently --time-setup) is specified, so there is no breaking change.

You had previously implied (in 2016: https://github.com/mochajs/mocha/pull/2244#issuecomment-225394691) that putting this behavior behind a flag and adding tests (which I have done) would be sufficient to get a PR like this accepted. I appreciate that it would be desirable to have more flexible, detailed timing information available but I am not prepared to implement the solution you described right now, and it would not accomplish my stated objective: include the duration of any beforeEach/setup hooks in the duration of tests, as seen by all reporters (not just a custom new one). I use multiple existing reporters for different purposes, and I like the format and content of the output; I just want to change what is included in the duration.

I believe this optional alternative definition of duration would be useful to other developers and teams as well. See #419, #700, and #1975, and articles such as Speeding up Javascript Test Time 1000x and Speeding Up Your JavaScript Test Suite which talk about the importance of the duration of setup hooks. Seeing where time is being spent (including setup time) is an essential part of making tests run faster (and keeping them fast) and currently mocha provides no visibility into the time for beforeEach/setup hooks.

[micdah]

For those wanting this kind of feature, I have come up with a hack way of adding it by using a hook:

let start = performance.now()
export const mochaHooks = {
    beforeEach: async function () {
        const currentTest = this.currentTest
        const originalRun = currentTest.run
        currentTest.run = function (fn) {
            originalRun.call(currentTest, function (...args) {
                const end = performance.now()
                currentTest.duration = Math.round(end - start)
                start = end
                fn(...args)
            })
        }
    }
}

It's put into a --require file which adds a global hook.

I have made it such that start is set immediately and updated after each test, this ensures all time spent between tests are included, so any before / beforeEach / after / afterEach etc. is counted in the duration.

It's kind of hackish, but works.

[JoshuaKGoldberg]

👋 coming back to this @sgilroy, are you still interested in working on this PR? As of https://github.com/mochajs/mocha/issues/5027 there are again maintainers who can review it now. No worries if you no longer have time - but if you do that'd be great!

I do see that your last message was discussing semver majoring of it - once we're ramped up we can pick up that thread of conversation.

[JoshuaKGoldberg]

Closing as it's been ~2 months. If anybody wants to pick up this change and re-uses code from this PR, please add a co-author attribution to the body of the PR. Cheers all! ☕ 🤎