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

Print progress only if enough time has passed. #701

Merged
merged 3 commits into from Jan 11, 2018

Conversation

Projects
None yet
3 participants
@jimhester
Member

jimhester commented Jan 10, 2018

Currently progress is printed after every test, which can cause a significant portion of the total test time taken to be used by printing if each test runs quickly. You also get a distracting flashing cursor when the updates occur too frequently.

As a real world example r-lib/fs@master...sanitize adds a bunch of tests which happen very fast, the total time taken for all tests in the fs package with the current master of testthat is ~5.973 seconds. With this PR the total time drops to is 4.254 seconds, a considerable change considering it is just test printing overhead.

This PR currently reuses the min_time parameter, which seems to work ok, 1/10 of a second is a reasonable amount of time between updates. But if necessary we could add an additional option or hardcode it to some other value.

@jimhester jimhester requested review from gaborcsardi and hadley Jan 10, 2018

⠹ | 1 2 | Expectations
⠸ | 1 3 | Expectations
⠼ | 1 4 | Expectations
⠴ | 2 4 | Expectations
✖ | 2 4 | Expectations

This comment has been minimized.

@gaborcsardi

gaborcsardi Jan 10, 2018

Member

Do you think it is possible to keep these lines? Because otherwise the tests are not really testing the output. Maybe by setting min_time?

Timing based tests are not too great in general, but of course in this case we can't really avoid them. We can have another set of (the same?) tests that set min_time to something very large, so that the output is omitted on very slow systems as well.

# Do not print if not enough time has passed since we last printed.
if ((time - self$last_time)[[3]] < self$min_time) {
return()
}

This comment has been minimized.

@gaborcsardi

gaborcsardi Jan 10, 2018

Member

I would always print a line at the beginning of a new context/file, so that you at least know which test file is running. I.e. this:

⠏ |  0       | Expectations

Otherwise, if the first test case takes very long, you'll have no output from the file for a long time.

@jimhester

This comment has been minimized.

Member

jimhester commented Jan 10, 2018

Ok I changed how this was implemented slightly, there is now a separate update_interval argument which when set to 0 uses the old behavior of updating every time a test completes, which we set when testing. I set update_interval to 0.1, but we can change it to something else if we find that doesn't update often enough.

@jimhester

This comment has been minimized.

Member

jimhester commented Jan 10, 2018

It also now should always update when there is a new context.

@@ -37,11 +39,13 @@ ProgressReporter <- R6::R6Class("ProgressReporter",
initialize = function(show_praise = TRUE,
max_failures = getOption("testthat.progress.max_fails", 10L),
min_time = 0.1,
update_interval = 0,

This comment has been minimized.

@gaborcsardi

gaborcsardi Jan 10, 2018

Member

Should the default be 0.1 here? Otherwise it is never throttled.

This comment has been minimized.

@jimhester

jimhester Jan 10, 2018

Member

Yeah, I changed the wrong value, thanks!

@@ -18,6 +18,8 @@ ProgressReporter <- R6::R6Class("ProgressReporter",
show_praise = TRUE,
min_time = 0.1,
start_time = NULL,
last_update = NULL,
update_interval = 0.1,

This comment has been minimized.

@gaborcsardi

gaborcsardi Jan 10, 2018

Member

It is a small thing, but I would set this to NULL here. It is set by initialize anyway, and then this magic number is misleading.

@gaborcsardi

This comment has been minimized.

Member

gaborcsardi commented Jan 10, 2018

Looks good, but the CI is failing. :(

@jimhester

This comment has been minimized.

Member

jimhester commented Jan 10, 2018

I missed setting update_interval = 0 for one test instance, should pass now 🤞

@hadley

hadley approved these changes Jan 10, 2018

I like the idea. Feel free to merge once you get the build failures resolved.

@@ -78,13 +82,19 @@ ProgressReporter <- R6::R6Class("ProgressReporter",
},
show_status = function(complete = FALSE) {
time <- proc.time()

This comment has been minimized.

@hadley

hadley Jan 10, 2018

Member

Does this get used somewhere?

This comment has been minimized.

@jimhester

jimhester Jan 11, 2018

Member

No it is vestigial, thanks for catching it.

time <- proc.time()
if (!is.null(self$last_update) &&
(time - self$last_update)[[3]] < self$update_interval) {

This comment has been minimized.

@hadley

hadley Jan 10, 2018

Member

Maybe just save proc.time()[[3]] to make a little simpler?

jimhester added some commits Jan 10, 2018

Turn off warnings on r-devel
The following WARNING currently happens to any package built on R-devel
with vignettes

> checking serialized R objects in the sources ... WARNING
> Found file(s) with version 3 serialization:
>   ‘build/vignette.rds’
> Such files are only readable in R >= 3.5.0.
> Recreate them with R < 3.5.0 or save(version = 2) or saveRDS(version =
> 2) as appropriate
@jimhester

This comment has been minimized.

Member

jimhester commented Jan 11, 2018

Thank you both for the reviews!

@jimhester jimhester merged commit 2ca7ac9 into r-lib:master Jan 11, 2018

1 check was pending

continuous-integration/travis-ci/pr The Travis CI build is in progress
Details
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment