Formating errors can be slow/variable

[bart1]

During package development I notices some errors were very slow to print. I used the test code below (slowness seems to relate to the number of records in i). As you see the example below with reprex is actually fast but if i call the code in Rstudio it takes 38 seconds in R 4.1.2 and 8 seconds in R 4.3.1 (I update R to see if that was the cause, rstudio version 2023.03.1). If I call R from the terminal it takes 2 seconds (independent of R version), this still seems a bit slow. As speed seems to scale with the size of i it seems to apply an operation to all elements of I while for these long vectors that would not be needed as only a limited number of elements are visualized. Maybe other can test if the code is also slow(ish) for them?

i<-1:10000
system.time(cli::format_error(
  "At least the following record not non-empty point:
                 {.val {i}}"
) |> message())
#> At least the following record not non-empty point: 1, 2, 3, 4, 5, 6, 7,
#> 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, …, 9999, and 10000
#>    user  system elapsed 
#>   0.215   0.004   0.219
sessioninfo::session_info()
#> ─ Session info ───────────────────────────────────────────────────────────────
#>  setting  value
#>  version  R version 4.1.2 (2021-11-01)
#>  os       Ubuntu 22.04.2 LTS
#>  system   x86_64, linux-gnu
#>  ui       X11
#>  language (EN)
#>  collate  en_US.UTF-8
#>  ctype    en_US.UTF-8
#>  tz       Europe/Amsterdam
#>  date     2023-07-07
#>  pandoc   2.19.2 @ /usr/lib/rstudio/resources/app/bin/quarto/bin/tools/ (via rmarkdown)
#> 
#> ─ Packages ───────────────────────────────────────────────────────────────────
#>  package     * version date (UTC) lib source
#>  cli           3.6.1   2023-03-23 [1] CRAN (R 4.1.2)
#>  digest        0.6.32  2023-06-26 [1] CRAN (R 4.1.2)
#>  evaluate      0.21    2023-05-05 [1] CRAN (R 4.1.2)
#>  fastmap       1.1.1   2023-02-24 [1] CRAN (R 4.1.2)
#>  fs            1.6.2   2023-04-25 [1] CRAN (R 4.1.2)
#>  glue          1.6.2   2022-02-24 [1] CRAN (R 4.1.2)
#>  htmltools     0.5.5   2023-03-23 [1] CRAN (R 4.1.2)
#>  knitr         1.43    2023-05-25 [1] CRAN (R 4.1.2)
#>  lifecycle     1.0.3   2022-10-07 [1] CRAN (R 4.1.2)
#>  magrittr      2.0.3   2022-03-30 [1] CRAN (R 4.1.2)
#>  purrr         1.0.1   2023-01-10 [1] CRAN (R 4.1.2)
#>  R.cache       0.16.0  2022-07-21 [1] CRAN (R 4.1.2)
#>  R.methodsS3   1.8.2   2022-06-13 [1] CRAN (R 4.1.2)
#>  R.oo          1.25.0  2022-06-12 [1] CRAN (R 4.1.2)
#>  R.utils       2.12.2  2022-11-11 [1] CRAN (R 4.1.2)
#>  reprex        2.0.2   2022-08-17 [1] CRAN (R 4.1.2)
#>  rlang         1.1.1   2023-04-28 [1] CRAN (R 4.1.2)
#>  rmarkdown     2.23    2023-07-01 [1] CRAN (R 4.1.2)
#>  rstudioapi    0.14    2022-08-22 [1] CRAN (R 4.1.2)
#>  sessioninfo   1.2.2   2021-12-06 [1] CRAN (R 4.1.2)
#>  styler        1.10.1  2023-06-05 [1] CRAN (R 4.1.2)
#>  vctrs         0.6.3   2023-06-14 [1] CRAN (R 4.1.2)
#>  withr         2.5.0   2022-03-03 [1] CRAN (R 4.1.2)
#>  xfun          0.39    2023-04-20 [1] CRAN (R 4.1.2)
#>  yaml          2.3.7   2023-01-23 [1] CRAN (R 4.1.2)
#> 
#>  [1] /home/bart/R/x86_64-pc-linux-gnu-library/4.1
#>  [2] /usr/local/lib/R/site-library
#>  [3] /usr/lib/R/site-library
#>  [4] /usr/lib/R/library
#> 
#> ──────────────────────────────────────────────────────────────────────────────

^{Created on 2023-07-07 with reprex v2.0.2}

[DanChaltiel]

Same here with cli 3.6.1 on R 4.1.3.

It takes about 8s for i=1:1000 in RStudio 2023.06.1 but is instantaneous in RGui or in reprex::reprex(). Running it inside callr::r() in RStudio yields 0.5s elapsed but takes 6.5s to run so this is probably happening during the printing/formatting for RStudio.

For a vector of length n, the time increases very linearly with n.

Code

library(tidyverse)
n = c(1,10,25,50,100,500,1000)
rslt = map(n, ~{
  i<-1:.x
  system.time(cli::cli_warn("xxx:{.val {i}}"))
})

rslt %>% 
  map(as_tibble_row) %>% 
  bind_rows() %>% 
  mutate(n=n, .before=1) %>% 
  mutate_all(as.numeric) %>% 
  select(-ends_with("child")) %>% 
  pivot_longer(-n) %>% 
  ggplot(aes(x=n, y=value, color=name)) +
  geom_point() + geom_line()

Same image using reprex

`callr`

a=Sys.time()
callr::r(\(){
  i<-1:1000
  system.time(cli::cli_warn("xxx:{.val {i}}"))
})
#   user  system elapsed 
#   0.48    0.02    0.53 
print(Sys.time()-a)
# Time difference of 6.562211 secs

[gaborcsardi]

Agreed.

[DanChaltiel]

This seems this be caused inside inline_generic(), where the format is applied to each member of the vector:

cli/R/inline.R

Line 34 in ef77a16

xx <- vcapply(xx, fmt)

Here is a smaller reprex:

fmt = cli:::create_ansi_style_fun(list(blue = list(open = "\033[34m", close = "\033[39m", palette = 5)))
system.time(sapply(1:200, fmt))
#>    user  system elapsed 
#>    0.63    0.20    0.82