Mocha: First unit test always slower than the others.

[danielserrao]

Prerequisites

• [x] Checked that your issue isn't already filed by cross referencing issues with the common mistake 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

For some reason the first unit test of my test suit is always slower than the others. When executing the tests in my console I get something like:

√ unit test A (483ms)
√ unit test B

But in the code if I change the unit test B to above the unit test A, I get this:
√ unit test B (470ms)
√ unit test A

For some reason the first unit tests gets always slower and because of that I think, the reason of being slow in not my code, but something in Mocha. At the same time I have others tests suits that are testing other code and it works fine, so I'm confused. Maybe is not Mocha, but due to not being sure, I need to ask if you have an idea of what can be happening.

The test is something like this:

let target = require('...');

describe('Module of unit tests', function () {
  this.timeout(1000);
  before(function () {
    ...
    target = proxyquire('...', {
      'node-chartist': sinon.stub().resolves('...'),
      'ws': function(){
        return {
          'close': function(){ /*Do nothing*/ },
          'send': function(){ /*Do nothing*/ },
          'on': function(arg, callback){
            ...
          }
        };
      }
    });
  });

  //Warning happens here
  it('unit test A', function () {
    ...
    target();
    ...
  });

  //If this unit test goes above unit test A, this will be the one to get the warning.
  it('unit test B', function () {
    ...
    target();
    ...
  });
})

Steps to Reproduce

I tried to reproduce in other projects without success, so I doubt you will be able to do it, but what I'm doing is:

1) Execute tests suit with unit test A above.
2) Execute tests suit with unit test B above.

Expected behavior: [What you expect to happen]
Don't get any warning about the time in both cases.

Actual behavior: [What actually happens]
The first unit test gets always a warning about the time.

Reproduces how often: [What percentage of the time does it reproduce?]
Around 90% of the times.

Versions

node v6.11.4
npm 3.10.10
mocha 4.0.1
sinon 4.1.2
chai 3.5.0
proxyquire 1.8.0

Additional Information

I used fiddler to make sure that while executing the unit tests, none network request was being made for the outside, to make sure that the delay is not caused by any network request.

I also debugged the code that the unit test is testing and I really don't see any reason for the delay in any case.

[ScottFreeCode]

One thing worth trying is copying everything that's common to the two tests, except for any assertions, into a before hook to see if simply running the same sort of stuff in another place makes the first place it runs of any sort slower, rather than the first test specifically.

It's possible that the code, even if it's not necessarily slow in general, is initializing something the first time that then gets saved in some way (e.g. Node's require cache, or filesystem-level caches of data from the disk, or a reuse optimization built into some library code), or that the JavaScript engine looks for optimizations in the code after it runs once, or something like that. You could also put it outside the testsuite altogether, although that's less likely to work -- for a few types of caches, that would have more chance of the cache running out somewhere in between loading the test files and actually running this particular file's tests (on the other hand, if a before hook worked and outside the testsuite didn't, that might narrow down what sort of caching or optimization is responsible...).

(And on a completely different note, more workaround than solution -- for anyone who just wants to suppress the time warning, there's the slow option to go with the timeout option.)

[danielserrao]

Hi ScottFreeCode,

Thanks for the response, it was very usefull. The problem was happening because I am making some stubs with proxyquire and by default the npm modules are loaded even when stubbed. In my case I have a module called node-chartist that was being loaded during the first unit test and that is why it was slower than the others.

To solve this problem I had to use the method noCallThru() of proxyquire which make proxyquire don't load any original dependencies.

Thanks for the help.

Kind regards,

Daniel Serrão

[ScottFreeCode]

Glad I could help you get that figured out! Let us know if there's anything else you need.