Mocha: Option to display describe times

[Nokel81]

Prerequisites

• [x] Checked that your issue hasn't already been filed by cross-referencing issues with the faq label
• [x] Checked next-gen ES issues and syntax problems by using the same environment and/or transpiler configuration without Mocha to ensure it isn't just a feature that actually isn't supported in the environment in question or a bug in your code.
• [x] 'Smoke tested' the code to be tested by running it outside the real test suite to get a better sense of whether the problem is in the code under test, your usage of Mocha, or Mocha itself
• [x] Ensured that there is no discrepancy between the locally and globally installed versions of Mocha. You can find them with: node node_modules/.bin/mocha --version(Local) and mocha --version(Global). We recommend avoiding the use of globally installed Mocha.

Description

This is a new feature request. Adding the --describe-duration option. This would print out at the end of every describe the total duration it took (including all before and after hooks).

This is very useful if trying to benchmark mocha for purposes of running the parts of a test suite in parallel on different nodes.

[ORESoftware]

describe is synchronous, always, so it should always be less than about 2ms

aka, describe never takes a callback or handles a returned promise, etc. describe is for registering async hooks (before, it, after, etc). It is suppose to register all of these in things in the same tick of the event loop, aka, synchronously.

[Nokel81]

So I guess what I mean is the length of all items within a describe. Also known as when running with this option a before and after are added surrounding the other hooks so that they are the first and last to run which then displays the time between each of those calls in the output of mocha

[ORESoftware]

I see what you mean. Next time add a code sample. You will probably have to do this manually, just do this:

describe('time this bitch', function(){
  let start;

   before(function(){
       start = Date.now();
   });
    //...

   after(function(){
      const totalTimeMillis = Date.now() - start;
    });
});

[Nokel81]

Yes like that except it would also print out the value and would be done for every single describe instead of having to do it manually

[ORESoftware]

Right so you would do it like this homie:

const handleTiming = function(time){

   before(function(){
       time.start = Date.now();
   });

   after(function(){
      const totalTimeMillis = Date.now() - time.start;
    });

}

describe('time this bitch', function(){
  let time  = {start: null};
  handleTiming(time);

  // ...

});

describe('time this bitch', function(){
  let time  = {start: null};
  handleTiming(time);

  // ...

});

[Nokel81]

Yes I could do that but there are two problems with this. One: it must be done to every single describe individually. Plus the logic to disable the printing if you don't want it. There is an advantage to having this being part of mocha by having it being able turn it off and on easily

[ORESoftware]

Yes I agree. another problem is that if you register the after first, another after would happen after it, if you follow. In other words, if there was more than 1 after hook, the timing would not include anything but the first after hook.

If you share your code that you want to do this with, it might help. The problem is that before/after run once after _all_ child blocks, not _each_ child block. So I can't figure out how to use inheritance to solve this.

[Nokel81]

So what you could do is if this is set then you define a function within mocha which then binds this to the function provided by the user

[Nokel81]

And defines the before and after surrounding the function being bound and then called

[ORESoftware]

not sure what you mean, have to show some code

[Nokel81]

Without having to look into the source code for mocha this is what I mean:

function (options, cb) {
    if (options.surround) {
        let diff = cb;
        const self = this;
        cb = function () {
            begin(...);
            diff.bind(self);
            after(...);
        };
    }
    ...
}

Where something like this should allow for the format to be transparent to that of the user but extend the function call with the correct this

[ORESoftware]

It's possible that an event could be fired whenever a describe block starts and ends, and those would get captured by the before/after blocks you want.

[Nokel81]

It is possible that that I think would be a larger change if such events are not currently in mocha

[ORESoftware]

I think those types events are already in Mocha, but I am not exactly sure how they are implemented.

[boneskull]

To be clear: you want to test the duration of an entire suite?

I can think of a hack. Use mocha --file timer.js where timer.js is:

beforeEach(function() {
  if (!this.currentTest.parent.timerStart) {
    this.currentTest.parent.timerIndex = 0;
    this.currentTest.parent.timerStart = Date.now();
  }
});

afterEach(function() {
  if (this.currentTest.parent.timerStart &&
    ++this.currentTest.parent.timerIndex ===
    this.currentTest.parent.tests.length) {
    console.error(`Suite "${this.currentTest.parent.fullTitle()}" Elapsed: ${Date.now() -
    this.currentTest.parent.timerStart}ms`);
  }
});

This will output the duration of every suite's tests, but it doesn't sum the durations from nested suites. It's a starting point, anyway.

[boneskull]

Fundamentally, Mocha should be collecting this information, but Mocha's stats collection is coupled too tightly to the reporting system. If someone wants to extract this from reporting, then we're talking... I don't want it to end up like

[boneskull]

I'm going to close this, as it's not immediately actionable. See #3256, then we can talk.