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

Already on GitHub? Sign in to your account

Tests take too long to fail #278

Closed
alexbirkett opened this Issue May 21, 2013 · 20 comments

Comments

Projects
None yet
7 participants

It takes more than 30 seconds for vows to fail 100 tests on my MacBook Pro! (details below). It takes only 0.021s for vows to pass 100 tests.

Setup details.
Vows version 0.7.0
Node version 0.10.6
Mac OS 10.8 running on a 2.8 GHz Intel Core i with 8GB of ram

Test code

var assert = require('assert');
var vows = require('vows');

var createTests = function () {
    return {
        'should call back after two seconds': {
            topic: function () {
                var callback = this.callback;
                process.nextTick(function() {
                    callback('error');
                });
            },
            'should fail fast': function (err, message, returnedData) {
                assert.isNull(err);
            }
        }
    };
};

var suite = vows.describe('test-vows');

var batch = {};
for (var i = 0; i < 100; i++) {
    batch['test ' + i] = createTests(i);
}
suite.addBatch(batch);

suite.export(module);

29.446s to pass 100 tests on a Ubuntu Linux 3.8.0 running on i5-2400 CPU @ 3.10GHz, 8GB of RAM.
During the test the top command indicates a node CPU usage of 100%, RAM usage is about 0,7%.

Contributor

adamstallard commented May 29, 2013

Anyone care to repeat their test with grunt-vows-runner as the test-runner instead of vows?

Contributor

adamstallard commented May 29, 2013

For me on windows 7, 3 core 2.9 ghz amd athlon II X3 435, 64 bit, it took 100% of one core, and 50 MB of ram.

It took 48s to fail all 100 tests and 0.026s to pass all 100 tests.

I will repeat the test using grunt-vows-runner soon.

Contributor

adamstallard commented May 29, 2013

Same results with grunt-vows-runner--it was a long shot :)

Contributor

adamstallard commented May 29, 2013

An interesting follow-up: If you let vows handle the error-handling for you, i.e.

        process.nextTick(function() {
          callback('error');
        });
      },
      'should fail fast': function () {
      }
    }

it will fail all 100 tests much faster:

.08s with vows and .02s with grunt-vows-runner

Contributor

adamstallard commented May 29, 2013

I've narrowed down the problem to vows' assert.isNull function.

If you use node's assert.ifError instead:

'should fail fast': function (err, message, returnedData) {
        assert.ifError(err);
      }

it runs much faster

I did it again with ifError() and results are the expected ones:
✗ Errored » 100 errored (0.019s)

Ubuntu Linux 3.8.0 i5-2400 CPU @ 3.10GHz, 8GB RAM

Thank you for the tip, this may probably have nothing to see with vows itself, but with assert-extras?
I could not find out quickly if the vows team has made its own implementation of assert-extras or not.

Contributor

ppmathis commented Aug 18, 2013

I've got exactly the same problem with vowsjs/api-easy@c4fc677. assert.isNull() works fine, but assert.isEqual() does not work... If I throw an error by myself, it is all fine.

try {
    assert.isNull(err);
    // When assert.equal isn't commented out, a test takes approximately 2 seconds to fail...
    assert.equal(res.statusCode, code);
} catch(err) {
    // The problem is related to the thrown error, if I throw an error by myself as said above, it works fine.
    // Example: throw new Error('This error works and fails fast!'); <-- works
    throw err;
}

"err" equals to:

{ name: 'AssertionError',
  actual: 404,
  expected: 200,
  operator: '==',
  message: 'expected {expected},\n\tgot\t {actual} ({operator})' }
Contributor

ppmathis commented Aug 18, 2013

Is this project still maintained? There are so many issues and the last commit is 2 months ago :/

Contributor

JerrySievert commented Aug 18, 2013

Yes, but it is one of many projects maintained by everyone involved. Pull requests are always welcome though!

Contributor

ppmathis commented Aug 18, 2013

Unfortunately I am not really familiar with the inner structure of vows, but I've managed to track down the error. As you can see in ./vows.js, AssertionErrors are handled different than normal errors:

// Starting on line 135
if (e.name && e.name.match(/AssertionError/)) {
    output('broken', e.toString().replace(/\`/g, '`'));
} else {
    output('errored', e.stack || e.message || e);
}

So, what's the reason for this huge delay of 2 seconds? You might not believe it, but the following function makes everything really slow & steady:

e.toString()

Yeah, that is correct, toString() is even slower than a turtle on drugs. You don't believe me? Try to replace e.toString().replace(//g, '') with any string literal, and you will see -> Aaah, it works blazingly fast! So, I went on with my exploration, and found that AssertionError.toString gets overriden in ./lib/assert/error.js. If I add some debug code in the function, I can see that it is called literally a thousand times, don't ask me why but that doesn't look good.

If I add this little line here, the bug is resolved and the method gots only called once, but there aren't any stack traces printed out:

// I add this little line here... *20th century fox intro* ... and it works.
this.stack = null;
// The following code is already in the source, starting on line 83
if (this.stack) {
   source = this.stack.match(/([a-zA-Z0-9._-]+\.(?:js|coffee))(:\d+):\d+/);
}

Unfortunately, if I only comment out the line with source = this.stack.match..., the delay is still there. So I tried to dig deeper, commented out my this.stack = null pseudo-fix and added the following piece of code:

console.log(arguments.callee.caller.toString());

So, what's the result? This little method recursively calls itself thousands of times, as long as this.stack isn't equal to null. Next try:

this.stack;     // Only this line => 2 seconds delay and a lot of recursive calls...
if(this.stack)  // Only this line => Same thing as above

/*
if (this.stack) {
    source = this.stack.match(/([a-zA-Z0-9._-]+\.(?:js|coffee))(:\d+):\d+/);
}
    */

Okay... Ò.ó So basically, as soon as you just use the variable this.stack in any possible way, the AssertionError.toString function calls itself many times and generates a huge delay of around 2 seconds. It's time for one last test:

console.log(this.hasOwnProperty('stack'));    // Returns true and does not delay

And that's all I can say so far. I've got literally NO idea, why this.stack acts in a such strange behavior... Maybe anyone could help me out?

Contributor

JerrySievert commented Aug 19, 2013

great detective work! i will try to take a look at this soon!

@ppmathis ppmathis added a commit to ppmathis/vows that referenced this issue Aug 20, 2013

@ppmathis ppmathis Fixed recursive call of assertion errors which led to a huge delay wh…
…en a test failed - Fixes vowsjs/vows#278
83b88d4
Contributor

ppmathis commented Aug 20, 2013

Made some small changes to the code (added 4 characters to be specific) and the problem is resolved. Now the toString() method doesn't get override anymore, toStringEx() will be used now. I think this.stack messes everything up as soon as the toString method gets overriden.

Maybe not the most beautiful solution, but it works like a charm on my system. (And all the tests are still passing.) Could someone maybe confirm that my fix works?

ping @JerrySievert @jokesterfr @adamstallard @alexbirkett

1 year and counting - is anyone going to bring @neoxid commit to master?

Contributor

adamstallard commented Nov 15, 2014

@neoxid

Pascal, can you do a pull request? It might make it more obvious that you have some code to check in.

Owner

indexzero commented Nov 17, 2014

@adamstallard @neoxid agreed. We don't know there are changes to bring in unless someone opens a pull request :(

@indexzero indexzero closed this in 5dced8e Nov 17, 2014

Owner

indexzero commented Nov 17, 2014

Cherry-picked the specific commit into master. Thanks!

Contributor

ppmathis commented Nov 17, 2014

Thank you @indexzero for cherry-picking my commit! Would have opened a pull request but was a bit too late in regards of replying. Anyways, issue solved!

Awesome! 👍

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment