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

Performance decrease in check_dots_empty0() and check_dots_empty() ? #1718

Open
etiennebacher opened this issue Jun 14, 2024 · 2 comments
Open

Comments

@etiennebacher
Copy link

etiennebacher commented Jun 14, 2024

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-
Copy link
Member

lionel- commented Jun 17, 2024

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
Copy link
Author

etiennebacher commented Jun 21, 2024

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()

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants