Performance regression (v2.3.0)

[Eluvias]

With the new version it takes more time to run the tests. I changed the reporter but still no improvement.

Do you confirm the performance regression?
Thanks.

## v2.3.0

# == Results =====================================================================
#   Duration: 19.6 s
#
# OK:       349
# Failed:   0
# Warnings: 0
# Skipped:  0

##  v2.2.1

# == Results =====================================================================
#   Duration: 3.4 s
#
# OK:       349
# Failed:   0
# Warnings: 0
# Skipped:  0

sessioninfo::session_info()
- Session info -----------------------------------------------------------------------------------------
 setting  value                       
 version  R version 3.6.0 (2019-04-26)
 os       Windows 7 x64 SP 1          
 system   x86_64, mingw32             
 ui       RStudio                     
 language (EN)                        
 collate  English_United Kingdom.1252 
 ctype    English_United Kingdom.1252 
 tz       Europe/London               
 date     2019-11-08                  

- Packages ---------------------------------------------------------------------------------------------
 package     * version date       lib source        
 assertthat    0.2.1   2019-03-21 [1] CRAN (R 3.6.0)
 cli           1.1.0   2019-03-19 [1] CRAN (R 3.6.0)
 crayon        1.3.4   2017-09-16 [1] CRAN (R 3.6.0)
 packrat       0.5.0   2018-11-14 [1] CRAN (R 3.6.0)
 rstudioapi    0.10    2019-03-19 [1] CRAN (R 3.6.0)
 sessioninfo   1.1.1   2018-11-05 [1] CRAN (R 3.6.0)
 withr         2.1.2   2018-03-15 [1] CRAN (R 3.6.0)

[hadley]

Could you please provide a reprex? It's hard to know what the problem is if you don't provide any code.

[jimhester]

I can reproduce a consistent slowdown (though with less magnitude) running the fs tests.

# testthat 2.3.0
Rscript -e 'devtools::test(reporter = "check")'  5.83s user 0.44s system 98% cpu 6.395 total
Rscript -e 'devtools::test(reporter = "check")'  5.85s user 0.41s system 98% cpu 6.362 total
Rscript -e 'devtools::test(reporter = "check")'  5.83s user 0.41s system 98% cpu 6.343 total
Rscript -e 'devtools::test(reporter = "check")'  5.90s user 0.43s system 98% cpu 6.440 total
Rscript -e 'devtools::test(reporter = "check")'  5.90s user 0.41s system 98% cpu 6.424 total

# testthat 2.2.1
Rscript -e 'devtools::test(reporter = "check")'  4.43s user 0.41s system 98% cpu 4.925 total
Rscript -e 'devtools::test(reporter = "check")'  4.45s user 0.41s system 98% cpu 4.953 total
Rscript -e 'devtools::test(reporter = "check")'  4.43s user 0.41s system 98% cpu 4.925 total
Rscript -e 'devtools::test(reporter = "check")'  4.37s user 0.41s system 97% cpu 4.891 total
Rscript -e 'devtools::test(reporter = "check")'  4.39s user 0.41s system 98% cpu 4.885 total

The last time this happened it was due to an increase in garbage collections due to an explicit gc() call. It doesn't look like there is a new gc(), but perhaps other changes are causing more collections to occur?

[jimhester]

There seems to be a fairly small increase in total GCs, the biggest change seemes to be an increase in total memory allocated, which would make the GCs take longer as well.

# testthat 2.3.0
bench::mark(devtools::test(reporter = "check"), iterations = 5)
#>   expression                           min median `itr/sec` mem_alloc `gc/sec` n_itr  n_gc total_time result memory
#>   <bch:expr>                         <bch> <bch:>     <dbl> <bch:byt>    <dbl> <int> <dbl>   <bch:tm> <list> <list>
#> 1 devtools::test(reporter = "check") 5.46s  5.58s     0.180     201MB     2.84     5    79      27.8s <tstt… <df[,…

# testthat 2.2.1
bench::mark(devtools::test(reporter = "check"), iterations = 5)
#>   expression                           min median `itr/sec` mem_alloc `gc/sec` n_itr  n_gc total_time result memory
#>   <bch:expr>                         <bch> <bch:>     <dbl> <bch:byt>    <dbl> <int> <dbl>   <bch:tm> <list> <list>
#> 1 devtools::test(reporter = "check") 3.84s  3.87s     0.257     125MB     3.75     5    73      19.5s <tstt… <df[,…

[hadley]

Profiling doesn't help because of the extreme depth of the call stack; @lionel-'s patch to R is likely to help, but it's most likely to be a small increase in overhead in every test_that() call.

[lionel-]

Maybe it depends on the kind of tests, for instance maybe error assertions are slower? Which package are you testing @Eluvias?

[Eluvias]

You might be right @lionel-; I run tests on a private repo which includes many error assertions.

#  testhat 2.2.1

# A tibble: 1 x 13
# expression                           min median `itr/sec` mem_alloc `gc/sec` n_itr  n_gc total_time result
# <bch:expr>                         <bch> <bch:>     <dbl> <bch:byt>    <dbl> <int> <dbl>   <bch:tm> <list>
#   1 devtools::test(reporter = "check") 2.31s 2.37s  0.418906 28.3MB  1.25672  5    15      11.9s <tstt~

# testhat 2.3.0

#  A tibble: 1 x 13
# expression                           min median `itr/sec` mem_alloc `gc/sec` n_itr  n_gc total_time result    
# <bch:expr>                         <bch> <bch:>     <dbl> <bch:byt>    <dbl> <int> <dbl>   <bch:tm> <list> 
#   1 devtools::test(reporter = "check") 17.9s 18.2s 0.0550637 147MB 0.539624   5    49      1.51m <tstt~

[lionel-]

Error expectations are the culprit:

bench::mark(
  before = expect_error(stop("foo"), "foo")
)[1:8]
#> # A tibble: 1 x 8
#>   expression      min   median `itr/sec` mem_alloc `gc/sec` n_itr  n_gc
#>   <bch:expr> <bch:tm> <bch:tm>     <dbl> <bch:byt>    <dbl> <int> <dbl>
#> 1 before        233µs    281µs     3356.        0B     7.31  1378     3

bench::mark(
  after = expect_error(stop("foo"), "foo")
)[1:8]
#> # A tibble: 1 x 8
#>   expression      min   median `itr/sec` mem_alloc `gc/sec` n_itr  n_gc
#>   <bch:expr> <bch:tm> <bch:tm>     <dbl> <bch:byt>    <dbl> <int> <dbl>
#> 1 after        3.79ms   4.26ms      226.    78.4KB     22.8    99    10

Most of the time is spent in cnd_entrace(). I'll look into entracing only when needed.

[lionel-]

A surprising amount of time is taken up by getNamespaceExports(), which is called to determine whether to format calls with :: or with :::.

I wonder if rlang::ns_exports() should memoise the results. One downside is that this would prevent garbage collection of exported functions from stale namespaces while developing with pkgload. Maybe it's worth it though.

We could also memoise for the duration of the top-level command, this way we allow garbage collection between invokations of devtools commands.

Edit: getNamespaceExports() returns only the names, not the functions, so there is no garbage collection issue.

[hadley]

Could you use exists() directly on the exports environment?

[lionel-]

Good idea! Down to 1.8 ms

bench::mark(exists = expect_error(stop("foo"), "foo"))[1:8]
#> # A tibble: 1 x 8
#>   expression      min   median `itr/sec` mem_alloc `gc/sec` n_itr  n_gc
#>   <bch:expr> <bch:tm> <bch:tm>     <dbl> <bch:byt>    <dbl> <int> <dbl>
#> 1 exists       1.62ms   1.82ms      525.        0B     13.0   242     6

Just need to be a bit careful with the base namespace:

ns_exports_has <- function(ns, name) {
  if (is_reference(ns, base_ns_env)) {
    exports <- base_pkg_env
  } else {
    exports <- ns$.__NAMESPACE__.$exports
  }
  !is_null(exports) && exists(name, envir = exports, inherits = FALSE)
}

[lionel-]

@Eluvias can you rerun your benchmark with the laster rlang master please?

[Eluvias]

# testthat     * 2.3.0.9000 2019-11-18 [1] Github (r-lib/testthat@8425c3f)

#> # A tibble: 1 x 8
#>  expression                              min   median `itr/sec` mem_alloc `gc/sec` n_itr  n_gc
#>  <bch:expr>                         <bch:tm> <bch:tm>     <dbl> <bch:byt>    <dbl> <int> <dbl>
#>1 devtools::test(reporter = "check")    21.1s    21.1s 0.0474156     152MB 0.616403     1    13

# testthat v2.2.1

#> # A tibble: 1 x 8
#>   expression                              min   median `itr/sec` mem_alloc `gc/sec` n_itr  n_gc
#>   <bch:expr>                         <bch:tm> <bch:tm>     <dbl> <bch:byt>    <dbl> <int> <dbl>
#> 1 devtools::test(reporter = "check")    2.52s    2.52s  0.396269    17.1MB  1.58508     1     4

# dev. version
== Results =====================================================================
Duration: 22.9 s

OK:       388
Failed:   0
Warnings: 0
Skipped:  0

#  v2.2.1
== Results =====================================================================
Duration: 2.1 s

OK:       388
Failed:   0
Warnings: 0
Skipped:  0

[lionel-]

@Eluvias Is this with the latest master of rlang? E.g. install_github("r-lib/rlang"). (There was no performance fix in dev testthat.)