slow (>1 minute) start up time when pointing to directory containing 15 files

[tony-kerz]

Description

strangely slow initialization time when pointing to directory

Config

  "ava": {
    "require": [
      "babel-register",
      "babel-polyfill"
    ]
  },

Command-Line Arguments

ava test/ava

Environment

ava --version 0.18.2
npm --versionNode.js v7.7.4
darwin 15.6.0

[novemberborn]

Could you provide timing details? How many files are in the other directories? Could this be related to #1288?

[tony-kerz]

i just timed it at 3m (ouch)...

i would be happy to instrument for more details if anyone can provide a specific technique to use.

here are some relevant file counts:

• node_modules: ~12k
• src: 104
• test/ava: 15
• test/cuke: 40

if i point to a specific file, it starts almost immediately, e.g:

ava -s test/ava/framework/data/data-test.js

fwiw, i typically run with the -s flag because some of the tests run against a database and will fail if run concurrently, but i have witnessed similar slowness without the -s flag...

[novemberborn]

i would be happy to instrument for more details if anyone can provide a specific technique to use.

That'd be great. Could you time how long this handlePaths() call takes? https://github.com/avajs/ava/blob/v0.18.2/lib/ava-files.js#L138:L145

if i point to a specific file, it starts almost immediately

Though that doesn't suggest it's a helper problem. Perhaps try with --concurrency 3 or something like that? I'm wondering if your tests just take a long time to load (and by default they're all loaded at once).

[tony-kerz]

hi mark,

i had some trouble attempting to use console to output timing (i guess ava hijacks stdout for it's spinner or such), but wrote some data to a file like so:

	findTestHelpers() {
		const begin = new Date();
		const result = handlePaths(defaultHelperPatterns(), ['!**/node_modules/**'], {
			cwd: this.cwd,
			includeUnderscoredFiles: true,
			cache: Object.create(null),
			statCache: Object.create(null),
			realpathCache: Object.create(null),
			symlinks: Object.create(null)
		});
		result.then(stuff => {
			fs.writeFile(
				'./temp-then',
				`elapsed=${new Date().getTime() - begin.getTime()}, result=${JSON.stringify(stuff, null, 2)}`
			);
		});
		return result;
	}

which yielded:

elapsed=756, result=[]

so looks like findTestHelpers is running fine?

--concurrency=3 makes the tests start sooner, but it still takes a long time to run all of them.

as an exercise, i was going to try to run each of the 15 ava files discretely and will report back those results, but open to other suggestions or instrumentations.

[ackerdev]

The improvement you're seeing with concurrency is documented here: #1318

If you have any potential information that might help debug that it would be greatly appreciated :)

[novemberborn]

--concurrency=3 makes the tests start sooner, but it still takes a long time to run all of them.

Seems to me like your tests are slow to start, and slow to run. Hard to give more pointers without seeing them though 😄

[tony-kerz]

so, i created a bash script to run the 15 test files separately with timers and indeed each file took about 15s to run which added up to about 3m, but...

i noticed that the first file ran in about 2 seconds.

so i commented out running a few of the files, but always the first one to run, runs in about 2 seconds and all subsequent run in about 15s...

so, i created this simple test:

import test from 'ava'
import _ from 'lodash'

test('_', t => {
  t.truthy(_.every([true], elt => elt))
})

and ran it twice in the same script, and lo and behold, the first time it runs in 2s and the second time in 15s...!?

so this script:

#!/bin/bash
set -o nounset
set -o errexit

echo "begin $SECONDS"
ava test/ava/canary-test.js
echo $SECONDS
ava test/ava/canary-test.js
echo "end $SECONDS"

yields this output:

~/g/blah (tk/jwt) $ script/ava.bash 
begin 0

  1 passed

3

  1 passed

end 16

i'm baffled, but does it mean anything to those more traveled?

[novemberborn]

i'm baffled, but does it mean anything to those more traveled?

But, those are separate AVA runs! That is baffling (and I don't have anything more to add, sorry).

[pixelass]

having problems here too. Ava has not been doing anything for about 10m.
I have the same problem with https://github.com/sindresorhus/xo/
Both packages use https://github.com/sindresorhus/globby and I am using globs in both cases.

foo/bar/baz/**/spec/*.js, foo/bar/baz/**/*.js

The project is HUGE but the folder I am targeting is actually very small and only has one test and about 10 js files.

I have never encountered the problem but have never used it in a project with so many folders.

[novemberborn]

I've been collecting globbing related issues under https://github.com/avajs/ava/labels/feature%3A%20globbing. I suspect this is one of them. Closing it though since the concerns are covered elsewhere.