Skip to content
New issue

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

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add timeout functionality #654

Merged
merged 2 commits into from Apr 5, 2016
Merged

Add timeout functionality #654

merged 2 commits into from Apr 5, 2016

Conversation

vadimdemedes
Copy link
Contributor

This PR fixes #8 and and #171.

Timeout can be set via --timeout or -T option. Values can be either numbers or set in a human-readable form:

$ ava --timeout=100 # 100 milliseconds
$ ava --timeout=2s # 2 seconds
$ ava --timeout=3m # 3 minutes

Timer resets after each completed test. So if there was 2 seconds (for example) of inactivity (no new test results), AVA exits with the following error message:

screen shot 2016-03-17 at 11 15 35 pm

P.S. test/fixture/long-running.js was renamed to test/fixture/slow-exit.js, because the new name is more appropriate for the represented test case.

@mention-bot
Copy link

By analyzing the blame information on this pull request, we identified @sotojuan, @floatdrop and @ingro to be potential reviewers

@@ -679,6 +680,20 @@ AVA automatically removes unrelated lines in stack traces, allowing you to find

<img src="media/stack-traces.png" width="300">

### Global timeout

A global timeout can be set via `--timeout` option.
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

A global timeout can be set via the --timeout option.

@sindresorhus
Copy link
Member

Shouldn't this be implemented in the API? timeout can be useful for other consumers too, like the grunt/gulp plugins.

@vadimdemedes
Copy link
Contributor Author

Shouldn't this be implemented in the API? timeout can be useful for other consumers too, like the grunt/gulp plugins.

Hm, probably, I'll push an update.


function onTimeout() {
logger.finish();
console.log(' ' + colors.error(figures.cross) + ' Exited because no new tests completed within last ' + cli.flags.timeout + ' of inactivity.');
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can remove the of inactivity bit I think. Should add ms.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah didn't read that closely enough 😄

@novemberborn
Copy link
Member

Shouldn't this be implemented in the API? timeout can be useful for other consumers too, like the grunt/gulp plugins.

The watcher should follow this behavior as well.


Clearing and restarting timers can be expensive. Would be good to investigate the performance overhead. One simple solution may be to never clear the timer but track when the last test completed. Then the next timeout can be scheduled so it fires timeout ms since completion.

Timers may sometimes fire a little early. Presumably this is only an issue when a very short timeout value is used though.

@vadimdemedes
Copy link
Contributor Author

Clearing and restarting timers can be expensive.

Could you provide any links backing this info?

@novemberborn
Copy link
Member

Could you provide any links backing this info?

There's the infamous "It sounds crazy, but disabling npm's progress bar yields a 2x npm install speed improvement for me" issue from a little while ago. See the 3.7.0 release notes and iarna/gauge@a7ab9c9.

Hard to say what the actual impact is on us of course.

};

Api.prototype._onTimeout = function () {
var message = 'Exited because no new tests completed within last ' + this.options.timeout + 'ms of inactivity';
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

completed within the last

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@vdemedes bump 😄

@sindresorhus
Copy link
Member

@vdemedes Can you fix the merge conflict?

@sindresorhus
Copy link
Member

Also discovered a problem with the timeout handling and its test being faulty:

import test from 'ava';
test.cb(t => {
    setTimeout(t.end, 10000);
});
$ ava --timeout=1s

This will output the error message after 10 seconds because of the setTimeout, not after 1s of inactivity. If you remove the setTimeout it will never exit. Can you also add a test where it never exits by itself?

@vadimdemedes
Copy link
Contributor Author

@sindresorhus Sure, will rebase tomorrow.

Will try to fix it, good catch ;)

@novemberborn
Copy link
Member

Hard to say what the actual impact is on us of course.

Does the bench stuff enable us to test this? (I've never used it before)

@jamestalmage
Copy link
Contributor

Does the bench stuff enable us to test this? (I've never used it before)

It should. Docs here. I would love a second set of eyeballs on our benchmark tooling! 😜

@novemberborn
Copy link
Member

I ran the benchmarks with 8d47119 and https://github.com/sindresorhus/ava/tree/timeout-no-clear. For the timeout tests I added this.options.timeout = '10s'; in api.js just before parsing. The results are below.

This PR seems to be the slowest overall. The no-clear implementation is pretty naive (it doesn't reschedule with a decreased interval) but seems to be the way to go.

┌────────────────────────────────────────────────┬────────────────────────────┬────────────────────────────┬────────────────────────────┬─────────────────────────────┐
│                                                │            mean            │           median           │            min             │             max             │
├────────────────────────────────────────────────┼──────────┬─────────┬───────┼──────────┬─────────┬───────┼──────────┬─────────┬───────┼──────────┬─────────┬────────┤
│ args                                           │ no-clear │ timeout │ pre   │ no-clear │ timeout │ pre   │ no-clear │ timeout │ pre   │ no-clear │ timeout │ pre    │
├────────────────────────────────────────────────┼──────────┼─────────┼───────┼──────────┼─────────┼───────┼──────────┼─────────┼───────┼──────────┼─────────┼────────┤
│ --verbose other/failures.js                    │ 1.838    │ 1.992   │ 1.813 │ 1.835    │ 1.988   │ 1.804 │ 1.826    │ 1.838   │ 1.79  │ 1.856    │ 2.195   │ 1.842  │
├────────────────────────────────────────────────┼──────────┼─────────┼───────┼──────────┼─────────┼───────┼──────────┼─────────┼───────┼──────────┼─────────┼────────┤
│ --verbose serial/alternating-sync-async.js     │ 3.227    │ 3.568   │ 3.264 │ 3.203    │ 3.569   │ 3.153 │ 3.176    │ 3.2     │ 3.123 │ 3.366    │ 3.703   │ 3.679  │
├────────────────────────────────────────────────┼──────────┼─────────┼───────┼──────────┼─────────┼───────┼──────────┼─────────┼───────┼──────────┼─────────┼────────┤
│ --verbose serial/async-immediate.js            │ 4.701    │ 5.134   │ 4.683 │ 4.661    │ 5.097   │ 4.615 │ 4.624    │ 4.691   │ 4.527 │ 4.847    │ 5.652   │ 5.028  │
├────────────────────────────────────────────────┼──────────┼─────────┼───────┼──────────┼─────────┼───────┼──────────┼─────────┼───────┼──────────┼─────────┼────────┤
│ --verbose serial/async-timeout.js              │ 5.983    │ 5.899   │ 5.948 │ 5.994    │ 6.073   │ 5.969 │ 5.888    │ 5.126   │ 5.868 │ 6.009    │ 6.33    │ 5.991  │
├────────────────────────────────────────────────┼──────────┼─────────┼───────┼──────────┼─────────┼───────┼──────────┼─────────┼───────┼──────────┼─────────┼────────┤
│ --verbose serial/sync.js                       │ 1.45     │ 1.737   │ 1.419 │ 1.437    │ 1.684   │ 1.418 │ 1.415    │ 1.59    │ 1.395 │ 1.537    │ 2.034   │ 1.443  │
├────────────────────────────────────────────────┼──────────┼─────────┼───────┼──────────┼─────────┼───────┼──────────┼─────────┼───────┼──────────┼─────────┼────────┤
│ --verbose concurrent/alternating-sync-async.js │ 2.057    │ 2.229   │ 1.945 │ 1.983    │ 2.154   │ 1.94  │ 1.973    │ 2.052   │ 1.892 │ 2.294    │ 2.468   │ 2.07   │
├────────────────────────────────────────────────┼──────────┼─────────┼───────┼──────────┼─────────┼───────┼──────────┼─────────┼───────┼──────────┼─────────┼────────┤
│ --verbose concurrent/async-immediate.js        │ 2.702    │ 3.024   │ 2.782 │ 2.701    │ 3.04    │ 2.687 │ 2.662    │ 2.831   │ 2.644 │ 2.734    │ 3.195   │ 3.341  │
├────────────────────────────────────────────────┼──────────┼─────────┼───────┼──────────┼─────────┼───────┼──────────┼─────────┼───────┼──────────┼─────────┼────────┤
│ --verbose concurrent/async-timeout.js          │ 2.694    │ 3.108   │ 2.76  │ 2.694    │ 3.082   │ 2.688 │ 2.671    │ 2.809   │ 2.64  │ 2.716    │ 3.563   │ 3.063  │
├────────────────────────────────────────────────┼──────────┼─────────┼───────┼──────────┼─────────┼───────┼──────────┼─────────┼───────┼──────────┼─────────┼────────┤
│ --verbose concurrent/sync.js                   │ 1.201    │ 1.39    │ 1.247 │ 1.201    │ 1.364   │ 1.215 │ 1.182    │ 1.335   │ 1.181 │ 1.215    │ 1.503   │ 1.408  │
├────────────────────────────────────────────────┼──────────┼─────────┼───────┼──────────┼─────────┼───────┼──────────┼─────────┼───────┼──────────┼─────────┼────────┤
│ --verbose concurrent/*.js serial/*.js          │ 9.77     │ 11.267  │ 9.824 │ 9.654    │ 11.255  │ 9.568 │ 9.579    │ 10.086  │ 9.413 │ 10.364   │ 12.382  │ 10.625 │
└────────────────────────────────────────────────┴──────────┴─────────┴───────┴──────────┴─────────┴───────┴──────────┴─────────┴───────┴──────────┴─────────┴────────┘

screen shot 2016-03-23 at 14 49 50

@vadimdemedes
Copy link
Contributor Author

@novemberborn Could you please explain the behavior and code behind that timeout-no-clear branch?

@novemberborn
Copy link
Member

@vdemedes timers are somewhat expensive to create. Rather than replacing an existing timer whenever a test completes I propose to let the existing timer run to completion. Then if tests have completed in the meantime we create a new timer. The delay for this new timer should be the configured timeout minus the time since the last test completed. This gets us the desired behavior without creating an unnecessary amount of timers.

This is what the timer-no-clear branch does, although it simply creates the new timer with the configured timeout. (The downside of that naive approach is that, worst case, it might actually take twice the timeout delay before the test run is aborted.)

@vadimdemedes
Copy link
Contributor Author

Anyone has ideas on how to fix this - #654 (comment)? The only way I see is process.exit().

This will output the error message after 10 seconds because of the setTimeout, not after 1s of inactivity. If you remove the setTimeout it will never exit. Can you also add a test where it never exits by itself?

@sindresorhus expect that it won't exit and .kill() it to finish the test?

@novemberborn
Copy link
Member

@vdemedes yea, I think we'd have to explicitly kill the forks and flag any remaining tests as having timed out. Of course they could be serial async tests in which case they wouldn't even have started but that nuance is probably not relevant.

@vadimdemedes
Copy link
Contributor Author

@novemberborn in timeout-no-clear, won't timeout be different from what user specified with --timeout? Update: never mind, I missed your comment:

it doesn't reschedule with a decreased interval

So we would need to calculate those intervals and take them into account. Sounds a bit over-complex for such a simple thing.

I pushed a new technique, ridiculously simple - debouncing. Instead of restarting timer after every test, this function is debounced with 200ms interval, so that it's not fired often. I believe it should improve things a lot.

It is simple and understandable, no black magic involved. Let me know what you think ;)

@novemberborn
Copy link
Member

It is simple and understandable, no black magic involved. Let me know what you think ;)

debounce still creates a timer though. This'll create fewer than your original approach but since we're effectively implementing our own kill-forks debouncer already why not go all the way?

@@ -180,6 +186,25 @@ Api.prototype._prefixTitle = function (file) {
return prefix;
};

Api.prototype._restartTimer = debounce(function () {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There is no need for this function using debounce.

Just do the following in the constructor:

if (this.options.timeout) {
  this._onTimeout = debounce(this._onTimeout, ms(this.options.timeout));
} else {
  this._onTimeout = noop;
}

I think that will be easier to understand (and faster) than the current implementation or the no-clear branch.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ha of course. It implements the approach I was advocating. Missed it due to context switching 😊

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Also, you shouldn't use debounce on a prototype method, as it will debounce across every instance and only call on the most recent.

sindresorhus/debounce#8

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The point of the latest update is to create less timers. That's why debounce should be on _restartTimer().

Also, you shouldn't use debounce on a prototype method, as it will debounce across every instance and only call on the most recent.

Agree.

@jamestalmage
Copy link
Contributor

Even with debounce there is an issue with this when someone has a long timeout set and the tests finish. There is no way to cancel the scheduled timer.

I've raised an issue: sindresorhus/debounce#9

@vadimdemedes
Copy link
Contributor Author

Even with debounce there is an issue with this when someone has a long timeout set and the tests finish. There is no way to cancel the scheduled timer.

This is not a problem, because we explicitly call process.exit() when the tests finish.

@novemberborn
Copy link
Member

@vdemedes I think you can use debounce all the way. Start it with the configured timeout and every time a test completes you call the debouncer again.

Even with debounce there is an issue with this when someone has a long timeout set and the tests finish. There is no way to cancel the scheduled timer.

This is not a problem, because we explicitly call process.exit() when the tests finish.

It will be a problem with the watcher. If we can't get cancel support upstream we'd need to track some state in the debouncer callback so it doesn't abort tests from newer test runs.

@vadimdemedes
Copy link
Contributor Author

It will be a problem with the watcher. If we can't get cancel support upstream we'd need to track some state in the debouncer callback so it doesn't abort tests from newer test runs.

In that case we have 3 choices:

  1. Disable timeouts and merge
  2. Wait for debounce module to support cancelling
  3. Find alternative module that supports cancelling already

I'm for 3.

@vadimdemedes
Copy link
Contributor Author

PR updated.

I re-implemented stats calculation in Runner, because it returned zero passCount, failCount, etc when timeout was reached and forks were killed. Now Runner returns current stats (including completed tests):

screen shot 2016-04-04 at 1 55 32 pm

I squashed all the timeout-related commits and left runner-related commit "outside". I'd like to keep it that way to maintain clear history.

@@ -13,8 +13,10 @@ var commonPathPrefix = require('common-path-prefix');
var resolveCwd = require('resolve-cwd');
var uniqueTempDir = require('unique-temp-dir');
var findCacheDir = require('find-cache-dir');
var debounce = require('lodash.debounce');
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

How does that compare to installing lodash and using the bellow?

var debounce = require('lodash/fp/debounce');

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

lodash.debounce contains only debounce() function, while lodash module contains all of them.

@sindresorhus
Copy link
Member

LGTM

@sindresorhus
Copy link
Member

@vdemedes #654 (comment)

@vadimdemedes
Copy link
Contributor Author

Updated ;)

@sindresorhus
Copy link
Member

@novemberborn @jamestalmage :shipit:

@jamestalmage
Copy link
Contributor

Yes - ship

@jamestalmage
Copy link
Contributor

Why is ae45752 in this PR?

@sindresorhus
Copy link
Member

@jamestalmage Explained in #654 (comment)

@jamestalmage
Copy link
Contributor

:shipit:

@sindresorhus sindresorhus merged commit e3e1752 into master Apr 5, 2016
@sindresorhus sindresorhus deleted the timeout branch April 5, 2016 10:23
@sindresorhus
Copy link
Member

Awesome‼️ Primo work @vdemedes

leo-happy

@novemberborn
Copy link
Member

Whoah that's a young DiCaprio 😲


I'm confused by ae45752. These counts are already computed in the _addTestResult() method in that same file. Was the change needed to get all results in case of a timeout? Then _addTestResult() needs to be cleaned up I think. Might not even need to expose the stats object.

@vadimdemedes
Copy link
Contributor Author

Was the change needed to get all results in case of a timeout?

Yes, exactly! When test worker needed to exit before tests completed, all stats were zero. So I implemented "on-demand" calculation of stats.

@sindresorhus Thanks :)

giphy 15

@novemberborn
Copy link
Member

Yes, exactly! When test worker needed to exit before tests completed, all stats were zero. So I implemented "on-demand" calculation of stats.

Can we remove the "on-test-complete" stats calculation then?

@vadimdemedes
Copy link
Contributor Author

@novemberborn Yes, definitely, I guess I forgot to remove it myself.

novemberborn added a commit that referenced this pull request Apr 6, 2016
Follow-up to #654. No longer collecting stats for every test that completes.
Explicitly return `null` when no exclusive tests could be run.
@novemberborn
Copy link
Member

@vdemedes see #728 😄

jamestalmage pushed a commit that referenced this pull request Apr 9, 2016
Follow-up to #654. No longer collecting stats for every test that completes.
Explicitly return `null` when no exclusive tests could be run.
@satya164
Copy link

satya164 commented May 5, 2016

Is there a way to see which tests exactly timed out?

@novemberborn
Copy link
Member

@satya164 not yet, #583 will help with that though.

@ash0080

This comment has been minimized.

@avajs avajs locked as resolved and limited conversation to collaborators Apr 7, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Timeout
8 participants