Ava: super slowdown with power assert / jsx / stateless component

[xjamundx]

Description

If you add a test that looks like this (add it 4 or 5x to get the full impact):

It will run fast

import test  from 'ava';
import { render } from 'react-dom'
import React from 'react';
function CustomComponent({ value }) { return <input value={value} /> }
test('does something fast', t => {
    const div = document.createElement('div')
    render(<CustomComponent value="3" />, div)
    const originInput = div.getElementsByTagName('input')[0]
    const val = originInput.value
    t.same(val, 33) // assert on a reference to the value
})

But if you do this it will be very slow

function CustomComponent({ value }) { return <input value={value} /> }
test('does something slow', t => {
    const div = document.createElement('div')
    render(<CustomComponent value="3" />, div)
    const originInput = div.getElementsByTagName('input')[0]
    t.same(originInput.value, 33) // assert directly on the value
})

Changing it to use assert will also make it run very fast, so this is probably a power-assert issue, but I don't know that as well.

In the little test case, it may add up to 1s to the full test output (timed with DEBUG=ava), but in my real life app it added 10s after the first test 20s after the second, etc until my tests just hung.

Possibly related to https://github.com/power-assert-js/power-assert/issues/34

Environment

Node.js v4.3.2
darwin 14.5.0

ava@latest and 0.9.2

[xjamundx]

I looked around a lot in the code, but eventually got lost, so any help would be awesome. Even if it's just a pointer at how to better test.

[kentcdodds]

To be clear, the difference is:

import test  from 'ava';
import { render } from 'react-dom'
import React from 'react';
function CustomComponent({ value }) { return <input value={value} /> }
+ test('does something slow', t => {
- test('does something fast', t => {
    const div = document.createElement('div')
    render(<CustomComponent value="3" />, div)
    const originInput = div.getElementsByTagName('input')[0]
-    const val = originInput.value
-    t.same(val, 33)
+    t.same(originInput.value, 33)
})

[kentcdodds]

I'm thinking that this may have more to do with the DOM node rather than JSX. If I'm not mistaken, @xjamundx is using jsdom.

[xjamundx]

Yeah JSDOM is probably getting us. Power assert is probably looping over the parent nodes or something and it infinite loops. A test timeout might have helped

[sindresorhus]

// @twada

[jamestalmage]

Does this happen only when tests fail, or even for passing tests?

If it is happening only for failing tests, then power-assert is the likely culprit. Otherwise it's probably something with JSX and deeper.

[xjamundx]

It is only happening for power-assert and it's only happening for failing tests.

The furthest I could figure out how to dive into the code was this which was very slow in these cases:
https://github.com/sindresorhus/ava/blob/45f96bd516a91bb0f9cec71b4e2664b712177e12/lib/runner.js#L111

[jamestalmage]

This is related to the fact that we serialize objects in the child thread and pass them to the parent thread for rendering by power-assert formatters. The React Dom exposes lots of internal state properties that we end up trying to serialize.

We did it this way because power-assert formatters introduce a non-trivial require time into tests.

Perhaps a better way would be to revert back to rendering error output in child threads, but lazy-require the formatters. Things would slow down a bit if you have errors in every test file, but should be just as fast if not faster if you have no errors or only have errors in one or two test files.

Alternatively, we could try to get the React Dom to expose less internal state (by making some properties non-enumerable). I wouldn't know where to begin with that. JSDOM appears to do a great job of hiding all internal state, so it's not that.

Update: I'm not sure the crossed out sections above are the problem.

[jamestalmage]

I just tried this on master:

global.document = require('jsdom').jsdom('<body></body>');
global.window = document.defaultView;
global.navigator = window.navigator;

import test  from 'ava';
import { render } from 'react-dom'
import React from 'react';
function CustomComponent({ value }) { return <input value={value} /> }

for (var i = 0; i < 100; i++) {

  (function (i) {
    test('does something slow ' + i, t => {
      const div = document.createElement('div')
      render(<CustomComponent value="3" />, div)
      const originInput = div.getElementsByTagName('input')[0]
      t.same(originInput.value, 33) // assert on a reference to the value
    })

  })(i)
}

With the following ava config in package.json:

  "ava": {
    "babel": {
      "presets": [
        "react",
        "stage-2",
        "es2015"
      ]
    }
  }

I get a runtime of ~2.0 seconds whether I use t.same or assert.deepStrictEqual.

[jamestalmage]

@xjamundx - Can you try against master?

$ npm install sindresorhus/ava

You will also need to set up your AVA config package.json to enable react. Either do what I did above, or use the inherit option:

"ava": {
  "babel": "inherit"
}

[xjamundx]

I'll try to come up with a better test case. I had repro'd this issue on master as of 2 days ago, but let me check. THANKS for looking very seriously into this.

[jamestalmage]

I just tried on 0.9.2 - your example is still fast.

[xjamundx]

I added a console.time around that line I mentioned earlier and basically in the fast 1 each test takes 1ms and in the slow one each test takes 50+ms. I'll send a more comprehensive test case tonight. Thanks for poking around at this.

[xjamundx]

Things start to compound when it's multiple files. As well. I did this in 10 files and the numbers are like this:

test: 119ms
test: 132ms
test: 130ms
test: 127ms
test: 132ms
test: 97ms
test: 96ms
test: 110ms
test: 101ms
test: 102ms
test: 75ms
test: 78ms
test: 86ms
test: 88ms
test: 92ms
test: 79ms

That was adding those lines in https://github.com/sindresorhus/ava/blob/45f96bd516a91bb0f9cec71b4e2664b712177e12/lib/runner.js#L111

    console.time('test')
    this.emit('test', props);
    console.timeEnd('test')

full test code (yes it's sloppy):

var jsdom = require('jsdom').jsdom;

global.document = jsdom('<body data-template-path=""></body>');
global.window = document.defaultView;
global.navigator = window.navigator;

// make sure to shim the global Intl if is missing
if (typeof Intl === 'undefined') {
        global.Intl = window.Intl = require('intl');
}

import test  from 'ava';
import { render } from 'react-dom'
import React from 'react';
function CustomComponent({ value }) { return <input value={value} /> }
var i = 0;
test('does something fast' + ++i, t => {
    const div = document.createElement('div')
    render(<CustomComponent value="3" />, div)
    const originInput = div.getElementsByTagName('input')[0]
    t.same(originInput.value, 33) // assert on a reference to the value
});
test('does something fast' + ++i, t => {
    const div = document.createElement('div')
    render(<CustomComponent value="3" />, div)
    const originInput = div.getElementsByTagName('input')[0]
    t.same(originInput.value, 33) // assert on a reference to the value
});
test('does something fast' + ++i, t => {
    const div = document.createElement('div')
    render(<CustomComponent value="3" />, div)
    const originInput = div.getElementsByTagName('input')[0]
    t.same(originInput.value, 33) // assert on a reference to the value
});
test('does something fast' + ++i, t => {
    const div = document.createElement('div')
    render(<CustomComponent value="3" />, div)
    const originInput = div.getElementsByTagName('input')[0]
    t.same(originInput.value, 33) // assert on a reference to the value
});
test('does something fast' + ++i, t => {
    const div = document.createElement('div')
    render(<CustomComponent value="3" />, div)
    const originInput = div.getElementsByTagName('input')[0]
    t.same(originInput.value, 33) // assert on a reference to the value
});
test('does something fast' + ++i, t => {
    const div = document.createElement('div')
    render(<CustomComponent value="3" />, div)
    const originInput = div.getElementsByTagName('input')[0]
    t.same(originInput.value, 33) // assert on a reference to the value
});
test('does something fast' + ++i, t => {
    const div = document.createElement('div')
    render(<CustomComponent value="3" />, div)
    const originInput = div.getElementsByTagName('input')[0]
    t.same(originInput.value, 33) // assert on a reference to the value
});
test('does something fast' + ++i, t => {
    const div = document.createElement('div')
    render(<CustomComponent value="3" />, div)
    const originInput = div.getElementsByTagName('input')[0]
    t.same(originInput.value, 33) // assert on a reference to the value
});
test('does something fast' + ++i, t => {
    const div = document.createElement('div')
    render(<CustomComponent value="3" />, div)
    const originInput = div.getElementsByTagName('input')[0]
    t.same(originInput.value, 33) // assert on a reference to the value
});
test('does something fast' + ++i, t => {
    const div = document.createElement('div')
    render(<CustomComponent value="3" />, div)
    const originInput = div.getElementsByTagName('input')[0]
    t.same(originInput.value, 33) // assert on a reference to the value
});
test('does something fast' + ++i, t => {
    const div = document.createElement('div')
    render(<CustomComponent value="3" />, div)
    const originInput = div.getElementsByTagName('input')[0]
    t.same(originInput.value, 33) // assert on a reference to the value
});
test('does something fast' + ++i, t => {
    const div = document.createElement('div')
    render(<CustomComponent value="3" />, div)
    const originInput = div.getElementsByTagName('input')[0]
    t.same(originInput.value, 33) // assert on a reference to the value
});
test('does something fast' + ++i, t => {
    const div = document.createElement('div')
    render(<CustomComponent value="3" />, div)
    const originInput = div.getElementsByTagName('input')[0]
    t.same(originInput.value, 33) // assert on a reference to the value
});
test('does something fast' + ++i, t => {
    const div = document.createElement('div')
    render(<CustomComponent value="3" />, div)
    const originInput = div.getElementsByTagName('input')[0]
    t.same(originInput.value, 33) // assert on a reference to the value
});
test('does something fast' + ++i, t => {
    const div = document.createElement('div')
    render(<CustomComponent value="3" />, div)
    const originInput = div.getElementsByTagName('input')[0]
    t.same(originInput.value, 33) // assert on a reference to the value
});
test('does something fast' + ++i, t => {
    const div = document.createElement('div')
    render(<CustomComponent value="3" />, div)
    const originInput = div.getElementsByTagName('input')[0]
    t.same(originInput.value, 33) // assert on a reference to the value
});
test('does something fast' + ++i, t => {
    const div = document.createElement('div')
    render(<CustomComponent value="3" />, div)
    const originInput = div.getElementsByTagName('input')[0]
    t.same(originInput.value, 33) // assert on a reference to the value
});

full test command:

./node_modules/.bin/ava --require babel-register test*.js

[jamestalmage]

The number of files is not going to have an impact. Each one gets it's own process. If you are using 0.9.2 you are paying a big price for multiple files, but that is not a React specific thing. Try on master.

[jamestalmage]

Also, make sure you have npm@3:

$ npm install -g npm@3
$ rm -rf node_modules
$ npm install

Babel is way more performant with npm@3, and if you are using [email protected] that is especially important.

[twada]

Perhaps a better way would be to revert back to rendering error output in child threads, but lazy-require the formatters. Things would slow down a bit if you have errors in every test file, but should be just as fast if not faster if you have no errors or only have errors in one or two test files.

Right.

[xjamundx]

I'll open a repo with just the tests I'm using tonight.

[xjamundx]

Narrowed it down a bit more. This super slowdown only appears when I pull in a massive dependency. Again, it's only slow when the test is failing AND i'm using power assert directly on the DOm element value AND when i'm using a massive dependency (react-intl in this case) in one of the modules that is being tested.

So it's clear to me now (Esp. with DEBUG=ava and the requiretime stuff) that the slowness I'm seeing is _directly_ related to require times.

Require times when I do this (this is example is just a single file with 2 tests in it):

t.same(input.value, amount + 2)

HUGE

Start time: (2016-03-09 07:09:52 UTC) [treshold=1%] #  module                                 time  %
 1  babel-types (../....es/lib/index.js)  146ms  ▇ 1%
 2  ./lib/api/node.js...lib/api/node.js)  264ms  ▇ 2%
 3  babel-core (../.....l-core/index.js)  265ms  ▇ 2%
 4  babel-register (....ter/lib/node.js)  307ms  ▇ 2%
 5  core-js/shim (../...core-js/shim.js)  225ms  ▇ 2%
 6  babel-polyfill (....ll/lib/index.js)  230ms  ▇ 2%
 7  cssstyle (../../....eDeclaration.js)  192ms  ▇ 1%
 8  ../level2/style (...level2/style.js)  206ms  ▇ 2%
 9  ./jsdom/living (....living/index.js)  334ms  ▇ 3%
10  jsdom (../../../....om/lib/jsdom.js)  347ms  ▇ 3%
11  /Users/jamufergus...tup-test-env.js)  899ms  ▇▇▇ 7%
12  ./lib/React (../....ct/lib/React.js)  165ms  ▇ 1%
13  react (../../../..../react/react.js)  165ms  ▇ 1%
14  react-intl (../.....t-intl/index.js)  261ms  ▇ 2%
15  ./i18n (../../../...8n/dist/i18n.js)  342ms  ▇ 3%
16  react-i18n (../.....n/dist/index.js)  342ms  ▇ 3%
17  ../Slow (../Slow.js)              707ms  ▇▇▇ 6%
18  /Users/jamufergus...SlowFields.js)  868ms  ▇▇▇ 7%
Total require(): 4115
Total time: 12.9s

vs.

const { value } = input
t.same(value, amount + 2)

Which results in

Start time: (2016-03-09 07:11:03 UTC) [treshold=1%]
#  module                                 time  %
1  got (node_modules/got/index.js)        42ms  ▇ 2%
2  package-json (nod...e-json/index.js)   47ms  ▇ 2%
3  latest-version (n...ersion/index.js)   47ms  ▇ 2%
4  update-notifier (...tifier/index.js)  102ms  ▇▇ 4%
5  meow (node_modules/meow/index.js)      27ms  ▇ 1%
6  bluebird (node_mo...ase/bluebird.js)   39ms  ▇ 1%
7  ./lib/create (nod...r/lib/create.js)   55ms  ▇ 2%
8  power-assert-form...matter/index.js)   56ms  ▇ 2%
9  ./api (node_modules/ava/api.js)        88ms  ▇▇ 3%
Total require(): 505
Total time: 2.7s

Close to a simplied test case I can upload, but not tonight, sorry..

Thanks again for all of your help

[twada]

@xjamundx Thank you for your great information.

Now I started wrestling with this issue

[xjamundx]

It must be fixed in a downstream dependency, because after uninstalling and reinstalling I can't reproduce anymore. Even on 0.9.2. Sorry for the wild goose chase. Previous attempts to install diff versions never uninstalled first, so some of the deps may have been stale.

:tada: thanks all for trying super hard to help here