Performance decrease in `check_dots_empty0()` and `check_dots_empty()` ?

[etiennebacher]

I’m not sure if something changed due to recent versions of R or if the version of RStudio plays a role here, but check_dots_empty0() seems very slow to me when ... are not empty.

library(rlang)

f <- function(x, ..., foofy = 8) {
  check_dots_empty0(...)
  x + foofy
}

try(f(1, 4))
#> Error in f(1, 4) : `...` must be empty.
#> ✖ Problematic argument:
#> • ..1 = 4
#> ℹ Did you forget to name an argument?

bench::mark(
  rlang_no_error = f(1),
  rlang_error = try(f(1, 4), silent = TRUE),
  check = FALSE,
  iterations = 50
)
#> # A tibble: 2 × 6
#>   expression          min   median `itr/sec` mem_alloc `gc/sec`
#>   <bch:expr>     <bch:tm> <bch:tm>     <dbl> <bch:byt>    <dbl>
#> 1 rlang_no_error    600ns    700ns 1091703.     21.2KB      0  
#> 2 rlang_error      31.1ms   35.3ms      26.5   186.6KB     31.1

Note that when I run this benchmark interactively and not in reprex I get a timing around 200ms for rlang_error.

Here’s a small function I used to do the same in base. There are probably features missing compared to check_dots_empty0(), it’s just to get an idea of the performance:

f2 <- function(x, ...) {
  dots <- eval(substitute(alist(...)))
  if (length(dots) > 0) {
    stop("foo")
  }
}
try(f2(1, 4))
#> Error in f2(1, 4) : foo

bench::mark(
  me_no_error = f2(1),
  me_error = try(f2(1, 4), silent = TRUE),
  check = FALSE,
  iterations = 50
)
#> # A tibble: 2 × 6
#>   expression       min   median `itr/sec` mem_alloc `gc/sec`
#>   <bch:expr>  <bch:tm> <bch:tm>     <dbl> <bch:byt>    <dbl>
#> 1 me_no_error    4.9µs    6.2µs   145603.    24.6KB        0
#> 2 me_error      64.8µs   70.5µs    11779.        0B        0

I’d just like to know if someone can reproduce those timings and whether this is normal.

Session info

RStudio version: RStudio 2024.04.1+748 "Chocolate Cosmos" Release (3ada7c6ddc8fcdb86a727a4f0ae467b9d9a7296c, 2024-05-07) for windows
Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) RStudio/2024.04.1+748 Chrome/120.0.6099.291 Electron/28.2.6 Safari/537.36, Quarto 1.4.550 (C:/Users/etienne/AppData/Local/Programs/Quarto/bin/quarto.exe)

sessioninfo::session_info()
#> ─ Session info ───────────────────────────────────────────────────────────────
#>  setting  value
#>  version  R version 4.4.1 RC (2024-06-06 r86715 ucrt)
#>  os       Windows 10 x64 (build 19045)
#>  system   x86_64, mingw32
#>  ui       RTerm
#>  language (EN)
#>  collate  English_Europe.utf8
#>  ctype    English_Europe.utf8
#>  tz       Europe/London
#>  date     2024-06-14
#>  pandoc   3.1.11 @ C:/Program Files/RStudio/resources/app/bin/quarto/bin/tools/ (via rmarkdown)
#> 
#> ─ Packages ───────────────────────────────────────────────────────────────────
#>  package     * version date (UTC) lib source
#>  bench         1.1.3   2023-05-04 [1] CRAN (R 4.4.0)
#>  cli           3.6.2   2023-12-11 [1] CRAN (R 4.4.0)
#>  digest        0.6.35  2024-03-11 [1] CRAN (R 4.4.0)
#>  evaluate      0.24.0  2024-06-10 [1] CRAN (R 4.4.1)
#>  fansi         1.0.6   2023-12-08 [1] CRAN (R 4.4.0)
#>  fastmap       1.2.0   2024-05-15 [1] CRAN (R 4.4.0)
#>  fs            1.6.4   2024-04-25 [1] CRAN (R 4.4.0)
#>  glue          1.7.0   2024-01-09 [1] CRAN (R 4.4.0)
#>  htmltools     0.5.8.1 2024-04-04 [1] CRAN (R 4.4.0)
#>  knitr         1.47    2024-05-29 [1] CRAN (R 4.4.0)
#>  lifecycle     1.0.4   2023-11-07 [1] CRAN (R 4.4.0)
#>  magrittr      2.0.3   2022-03-30 [1] CRAN (R 4.4.0)
#>  pillar        1.9.0   2023-03-22 [1] CRAN (R 4.4.0)
#>  pkgconfig     2.0.3   2019-09-22 [1] CRAN (R 4.4.0)
#>  profmem       0.6.0   2020-12-13 [1] CRAN (R 4.4.0)
#>  purrr         1.0.2   2023-08-10 [1] CRAN (R 4.4.0)
#>  R.cache       0.16.0  2022-07-21 [1] CRAN (R 4.4.0)
#>  R.methodsS3   1.8.2   2022-06-13 [1] CRAN (R 4.4.0)
#>  R.oo          1.26.0  2024-01-24 [1] CRAN (R 4.4.0)
#>  R.utils       2.12.3  2023-11-18 [1] CRAN (R 4.4.0)
#>  reprex        2.1.0   2024-01-11 [1] CRAN (R 4.4.0)
#>  rlang       * 1.1.4   2024-06-14 [1] Github (r-lib/rlang@ae699d1)
#>  rmarkdown     2.27    2024-05-17 [1] CRAN (R 4.4.0)
#>  rstudioapi    0.16.0  2024-03-24 [1] CRAN (R 4.4.0)
#>  sessioninfo   1.2.2   2021-12-06 [1] CRAN (R 4.4.0)
#>  styler        1.10.3  2024-04-07 [1] CRAN (R 4.4.0)
#>  tibble        3.2.1   2023-03-20 [1] CRAN (R 4.4.0)
#>  utf8          1.2.4   2023-10-22 [1] CRAN (R 4.4.0)
#>  vctrs         0.6.5   2023-12-01 [1] CRAN (R 4.4.0)
#>  withr         3.0.0   2024-01-16 [1] CRAN (R 4.4.0)
#>  xfun          0.44    2024-05-15 [1] CRAN (R 4.4.0)
#>  yaml          2.3.8   2023-12-11 [1] CRAN (R 4.4.0)
#> 
#>  [1] C:/Users/etienne/AppData/Local/Programs/R/R-4.4.1rc/library
#> 
#> ──────────────────────────────────────────────────────────────────────────────

[lionel-]

Our error paths are not particularly optimised. Part of the overhead you're measuring is from our abort() and cli stack (try using abort() instead of stop() in your benchmark). The rest of this overhead might be worth taking a look.

[etiennebacher]

With abort() instead of stop():

library(rlang)

f2 <- function(x, ...) {
  dots <- eval(substitute(alist(...)))
  if (length(dots) > 0) {
    abort("foo")
  }
}

bench::mark(
  me_no_error = f2(1),
  me_error = try(f2(1, 4), silent = TRUE),
  check = FALSE,
  iterations = 50
)
#> # A tibble: 2 × 6
#>   expression       min   median `itr/sec` mem_alloc `gc/sec`
#>   <bch:expr>  <bch:tm> <bch:tm>     <dbl> <bch:byt>    <dbl>
#> 1 me_no_error    4.9µs    5.1µs   179211.        0B      0  
#> 2 me_error      7.52ms   8.13ms      120.    5.33MB     16.4

Most of the difference in timing seems to come from check_dots_empty0()