super slowdown with power assert / jsx / stateless component #616

xjamundx · 2016-03-08T00:32:21Z

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 power-assert-js/power-assert#34

Environment

Node.js v4.3.2
darwin 14.5.0

ava@latest and 0.9.2

The text was updated successfully, but these errors were encountered:

xjamundx · 2016-03-08T00:36:26Z

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 · 2016-03-08T00:37:09Z

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 · 2016-03-08T00:38:58Z

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 · 2016-03-08T00:39:28Z

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 · 2016-03-08T05:59:23Z

// @twada

jamestalmage · 2016-03-08T22:40:52Z

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 · 2016-03-08T22:45:50Z

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 · 2016-03-08T23:55:15Z

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 · 2016-03-09T00:29:17Z

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 · 2016-03-09T00:33:16Z

@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 · 2016-03-09T01:01:48Z

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 · 2016-03-09T01:33:59Z

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

xjamundx · 2016-03-09T02:33:19Z

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 · 2016-03-09T02:36:26Z

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 · 2016-03-09T02:49:50Z

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 · 2016-03-09T03:01:39Z

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 · 2016-03-09T04:47:18Z

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 · 2016-03-09T05:16:14Z

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

xjamundx · 2016-03-09T07:17:05Z

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 · 2016-03-09T15:48:16Z

@xjamundx Thank you for your great information.

Now I started wrestling with this issue

xjamundx · 2016-03-10T05:07:06Z

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.

🎉 thanks all for trying super hard to help here

sindresorhus added the bug current functionality does not work as desired label Mar 8, 2016

xjamundx closed this as completed Mar 10, 2016

maur8ino mentioned this issue Mar 10, 2016

Updates AVA to v0.13 Granze/react-starterify#35

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

super slowdown with power assert / jsx / stateless component #616

super slowdown with power assert / jsx / stateless component #616

xjamundx commented Mar 8, 2016

xjamundx commented Mar 8, 2016

kentcdodds commented Mar 8, 2016

kentcdodds commented Mar 8, 2016

xjamundx commented Mar 8, 2016

sindresorhus commented Mar 8, 2016

jamestalmage commented Mar 8, 2016

xjamundx commented Mar 8, 2016

jamestalmage commented Mar 8, 2016

jamestalmage commented Mar 9, 2016

jamestalmage commented Mar 9, 2016

xjamundx commented Mar 9, 2016

jamestalmage commented Mar 9, 2016

xjamundx commented Mar 9, 2016

xjamundx commented Mar 9, 2016

jamestalmage commented Mar 9, 2016

jamestalmage commented Mar 9, 2016

twada commented Mar 9, 2016

xjamundx commented Mar 9, 2016

xjamundx commented Mar 9, 2016

twada commented Mar 9, 2016

xjamundx commented Mar 10, 2016

super slowdown with power assert / jsx / stateless component #616

super slowdown with power assert / jsx / stateless component #616

Comments

xjamundx commented Mar 8, 2016

Description

Environment

xjamundx commented Mar 8, 2016

kentcdodds commented Mar 8, 2016

kentcdodds commented Mar 8, 2016

xjamundx commented Mar 8, 2016

sindresorhus commented Mar 8, 2016

jamestalmage commented Mar 8, 2016

xjamundx commented Mar 8, 2016

jamestalmage commented Mar 8, 2016

jamestalmage commented Mar 9, 2016

jamestalmage commented Mar 9, 2016

xjamundx commented Mar 9, 2016

jamestalmage commented Mar 9, 2016

xjamundx commented Mar 9, 2016

xjamundx commented Mar 9, 2016

jamestalmage commented Mar 9, 2016

jamestalmage commented Mar 9, 2016

twada commented Mar 9, 2016

xjamundx commented Mar 9, 2016

xjamundx commented Mar 9, 2016

twada commented Mar 9, 2016

xjamundx commented Mar 10, 2016