vignettes/progress-benchmark.Rmd
progress-benchmark.Rmd
We make sure that the timer is not TRUE
, by setting it
to ten hours.
library(cli)
# 10 hours
cli:::cli_tick_set(10 * 60 * 60 * 1000)
cli_tick_reset()
#> NULL
`__cli_update_due`
#> [1] FALSE
fun <- function() NULL
ben_st <- bench::mark(
`__cli_update_due`,
fun(),
.Call(ccli_tick_reset),
interactive(),
check = FALSE
)
ben_st
#> # A tibble: 4 × 6
#> expression min median `itr/sec` mem_alloc `gc/sec`
#> <bch:expr> <bch:tm> <bch:tm> <dbl> <bch:byt> <dbl>
#> 1 __cli_update_due 7.92ns 12ns 76461204. 0B 0
#> 2 fun() 89.06ns 205.9ns 3491271. 0B 0
#> 3 .Call(ccli_tick_reset) 83.94ns 93.9ns 8243099. 0B 0
#> 4 interactive() 13.97ns 20ns 38529251. 0B 0
ben_st2 <- bench::mark(
if (`__cli_update_due`) foobar()
)
ben_st2
#> # A tibble: 1 × 6
#> expression min median `itr/sec` mem_alloc `gc/sec`
#> <bch:expr> <bch:tm> <bch:t> <dbl> <bch:byt> <dbl>
#> 1 if (`__cli_update_due`) foobar() 25ns 93.9ns 12148926. 0B 0
cli_progress_along()
seq <- 1:100000
ta <- cli_progress_along(seq)
bench::mark(seq[[1]], ta[[1]])
#> # A tibble: 2 × 6
#> expression min median `itr/sec` mem_alloc `gc/sec`
#> <bch:expr> <bch:tm> <bch:tm> <dbl> <bch:byt> <dbl>
#> 1 seq[[1]] 95ns 105ns 7094556. 0B 0
#> 2 ta[[1]] 105ns 114ns 7423258. 0B 0
for
loop
This is the baseline:
f0 <- function(n = 1e5) {
x <- 0
seq <- 1:n
for (i in seq) {
x <- x + i %% 2
}
x
}
With progress bars:
fp <- function(n = 1e5) {
x <- 0
seq <- 1:n
for (i in cli_progress_along(seq)) {
x <- x + seq[[i]] %% 2
}
x
}
Overhead per iteration:
ben_taf <- bench::mark(f0(), fp())
ben_taf
#> # A tibble: 2 × 6
#> expression min median `itr/sec` mem_alloc `gc/sec`
#> <bch:expr> <bch:tm> <bch:tm> <dbl> <bch:byt> <dbl>
#> 1 f0() 8.54ms 8.91ms 110. 21.6KB 483.
#> 2 fp() 9.87ms 10.48ms 96.2 82.3KB 454.
(ben_taf$median[2] - ben_taf$median[1]) / 1e5
#> [1] 15.7ns
ben_taf2 <- bench::mark(f0(1e6), fp(1e6))
#> Warning: Some expressions had a GC in every iteration; so filtering is
#> disabled.
ben_taf2
#> # A tibble: 2 × 6
#> expression min median `itr/sec` mem_alloc `gc/sec`
#> <bch:expr> <bch:tm> <bch:tm> <dbl> <bch:byt> <dbl>
#> 1 f0(1e+06) 109ms 143ms 6.59 0B 54.4
#> 2 fp(1e+06) 115ms 117ms 8.50 1.88KB 69.7
(ben_taf2$median[2] - ben_taf2$median[1]) / 1e6
#> [1] 1ns
ben_taf3 <- bench::mark(f0(1e7), fp(1e7))
#> Warning: Some expressions had a GC in every iteration; so filtering is
#> disabled.
ben_taf3
#> # A tibble: 2 × 6
#> expression min median `itr/sec` mem_alloc `gc/sec`
#> <bch:expr> <bch:tm> <bch:tm> <dbl> <bch:byt> <dbl>
#> 1 f0(1e+07) 1.16s 1.16s 0.864 0B 71.7
#> 2 fp(1e+07) 1.36s 1.36s 0.733 1.88KB 60.8
(ben_taf3$median[2] - ben_taf3$median[1]) / 1e7
#> [1] 20.7ns
ben_taf4 <- bench::mark(f0(1e8), fp(1e8))
#> Warning: Some expressions had a GC in every iteration; so filtering is
#> disabled.
ben_taf4
#> # A tibble: 2 × 6
#> expression min median `itr/sec` mem_alloc `gc/sec`
#> <bch:expr> <bch:tm> <bch:tm> <dbl> <bch:byt> <dbl>
#> 1 f0(1e+08) 11.5s 11.5s 0.0871 0B 33.7
#> 2 fp(1e+08) 12.1s 12.1s 0.0825 1.88KB 29.9
(ben_taf4$median[2] - ben_taf4$median[1]) / 1e8
#> [1] 6.41ns
lapply()
This is the baseline:
With an index vector:
f01 <- function(n = 1e5) {
seq <- 1:n
ret <- lapply(seq_along(seq), function(i) {
seq[[i]] %% 2
})
invisible(ret)
}
With progress bars:
fp <- function(n = 1e5) {
seq <- 1:n
ret <- lapply(cli_progress_along(seq), function(i) {
seq[[i]] %% 2
})
invisible(ret)
}
Overhead per iteration:
ben_tam <- bench::mark(f0(), f01(), fp())
#> Warning: Some expressions had a GC in every iteration; so filtering is
#> disabled.
ben_tam
#> # A tibble: 3 × 6
#> expression min median `itr/sec` mem_alloc `gc/sec`
#> <bch:expr> <bch:tm> <bch:tm> <dbl> <bch:byt> <dbl>
#> 1 f0() 64.7ms 73.5ms 13.0 781KB 20.4
#> 2 f01() 111.4ms 117ms 8.19 781KB 14.7
#> 3 fp() 113.3ms 161ms 5.55 783KB 8.32
(ben_tam$median[3] - ben_tam$median[1]) / 1e5
#> [1] 875ns
ben_tam2 <- bench::mark(f0(1e6), f01(1e6), fp(1e6))
#> Warning: Some expressions had a GC in every iteration; so filtering is
#> disabled.
ben_tam2
#> # A tibble: 3 × 6
#> expression min median `itr/sec` mem_alloc `gc/sec`
#> <bch:expr> <bch:tm> <bch:tm> <dbl> <bch:byt> <dbl>
#> 1 f0(1e+06) 742.79ms 742.79ms 1.35 7.63MB 8.08
#> 2 f01(1e+06) 1.27s 1.27s 0.789 7.63MB 6.31
#> 3 fp(1e+06) 1.44s 1.44s 0.693 7.63MB 4.85
(ben_tam2$median[3] - ben_tam2$median[1]) / 1e6
#> [1] 701ns
(ben_tam2$median[3] - ben_tam2$median[2]) / 1e6
#> [1] 177ns
This is the baseline:
f0 <- function(n = 1e5) {
seq <- 1:n
ret <- purrr::map(seq, function(x) {
x %% 2
})
invisible(ret)
}
With index vector:
f01 <- function(n = 1e5) {
seq <- 1:n
ret <- purrr::map(seq_along(seq), function(i) {
seq[[i]] %% 2
})
invisible(ret)
}
With progress bars:
fp <- function(n = 1e5) {
seq <- 1:n
ret <- purrr::map(cli_progress_along(seq), function(i) {
seq[[i]] %% 2
})
invisible(ret)
}
Overhead per iteration:
ben_pur <- bench::mark(f0(), f01(), fp())
ben_pur
#> # A tibble: 3 × 6
#> expression min median `itr/sec` mem_alloc `gc/sec`
#> <bch:expr> <bch:tm> <bch:tm> <dbl> <bch:byt> <dbl>
#> 1 f0() 53.4ms 56.7ms 16.7 1.39MB 9.99
#> 2 f01() 66.6ms 74.4ms 13.6 781.3KB 5.43
#> 3 fp() 69.1ms 74.7ms 13.5 783.24KB 10.1
(ben_pur$median[3] - ben_pur$median[1]) / 1e5
#> [1] 180ns
(ben_pur$median[3] - ben_pur$median[2]) / 1e5
#> [1] 2.98ns
ben_pur2 <- bench::mark(f0(1e6), f01(1e6), fp(1e6))
#> Warning: Some expressions had a GC in every iteration; so filtering is
#> disabled.
ben_pur2
#> # A tibble: 3 × 6
#> expression min median `itr/sec` mem_alloc `gc/sec`
#> <bch:expr> <bch:tm> <bch:tm> <dbl> <bch:byt> <dbl>
#> 1 f0(1e+06) 772.25ms 772.25ms 1.29 7.63MB 3.88
#> 2 f01(1e+06) 1s 1s 0.996 7.63MB 3.98
#> 3 fp(1e+06) 1.35s 1.35s 0.738 7.63MB 2.95
(ben_pur2$median[3] - ben_pur2$median[1]) / 1e6
#> [1] 583ns
(ben_pur2$median[3] - ben_pur2$median[2]) / 1e6
#> [1] 351ns
ticking()
f0 <- function(n = 1e5) {
i <- 0
x <- 0
while (i < n) {
x <- x + i %% 2
i <- i + 1
}
x
}
ben_tk <- bench::mark(f0(), fp())
#> Warning: Some expressions had a GC in every iteration; so filtering is
#> disabled.
ben_tk
#> # A tibble: 2 × 6
#> expression min median `itr/sec` mem_alloc `gc/sec`
#> <bch:expr> <bch:tm> <bch:tm> <dbl> <bch:byt> <dbl>
#> 1 f0() 10.46ms 17.58ms 55.9 39.3KB 3.99
#> 2 fp() 5.12s 5.12s 0.195 100.4KB 2.34
(ben_tk$median[2] - ben_tk$median[1]) / 1e5
#> [1] 51µs
f0 <- function(n = 1e5) {
x <- 0
for (i in 1:n) {
x <- x + i %% 2
}
x
}
fp <- function(n = 1e5) {
cli_progress_bar(total = n)
x <- 0
for (i in 1:n) {
x <- x + i %% 2
cli_progress_update()
}
x
}
ff <- function(n = 1e5) {
cli_progress_bar(total = n)
x <- 0
for (i in 1:n) {
x <- x + i %% 2
if (`__cli_update_due`) cli_progress_update()
}
x
}
ben_api <- bench::mark(f0(), ff(), fp())
#> Warning: Some expressions had a GC in every iteration; so filtering is
#> disabled.
ben_api
#> # A tibble: 3 × 6
#> expression min median `itr/sec` mem_alloc `gc/sec`
#> <bch:expr> <bch:tm> <bch:tm> <dbl> <bch:byt> <dbl>
#> 1 f0() 8.98ms 9.74ms 85.0 18.7KB 9.88
#> 2 ff() 15.62ms 16.45ms 55.9 27.6KB 5.99
#> 3 fp() 1.84s 1.84s 0.544 25.1KB 3.26
(ben_api$median[3] - ben_api$median[1]) / 1e5
#> [1] 18.3µs
(ben_api$median[2] - ben_api$median[1]) / 1e5
#> [1] 67.1ns
ben_api2 <- bench::mark(f0(1e6), ff(1e6), fp(1e6))
#> Warning: Some expressions had a GC in every iteration; so filtering is
#> disabled.
ben_api2
#> # A tibble: 3 × 6
#> expression min median `itr/sec` mem_alloc `gc/sec`
#> <bch:expr> <bch:tm> <bch:tm> <dbl> <bch:byt> <dbl>
#> 1 f0(1e+06) 100.3ms 101.5ms 9.63 0B 11.6
#> 2 ff(1e+06) 158.9ms 177ms 5.83 1.9KB 5.83
#> 3 fp(1e+06) 20.5s 20.5s 0.0487 1.9KB 2.92
(ben_api2$median[3] - ben_api2$median[1]) / 1e6
#> [1] 20.4µs
(ben_api2$median[2] - ben_api2$median[1]) / 1e6
#> [1] 75.5ns
Baseline function:
SEXP test_baseline() {
int i;
int res = 0;
for (i = 0; i < 2000000000; i++) {
res += i % 2;
}
return ScalarInteger(res);
}
Switch + modulo check:
SEXP test_modulo(SEXP progress) {
int i;
int res = 0;
int progress_ = LOGICAL(progress)[0];
for (i = 0; i < 2000000000; i++) {
if (i % 10000 == 0 && progress_) cli_progress_set(R_NilValue, i);
res += i % 2;
}
return ScalarInteger(res);
}
cli progress bar API:
SEXP test_cli() {
int i;
int res = 0;
SEXP bar = PROTECT(cli_progress_bar(2000000000, NULL));
for (i = 0; i < 2000000000; i++) {
if (CLI_SHOULD_TICK) cli_progress_set(bar, i);
res += i % 2;
}
cli_progress_done(bar);
UNPROTECT(1);
return ScalarInteger(res);
}
SEXP test_cli_unroll() {
int i = 0;
int res = 0;
SEXP bar = PROTECT(cli_progress_bar(2000000000, NULL));
int s, final, step = 2000000000 / 100000;
for (s = 0; s < 100000; s++) {
if (CLI_SHOULD_TICK) cli_progress_set(bar, i);
final = (s + 1) * step;
for (i = s * step; i < final; i++) {
res += i % 2;
}
}
cli_progress_done(bar);
UNPROTECT(1);
return ScalarInteger(res);
}
library(progresstest)
ben_c <- bench::mark(
test_baseline(),
test_modulo(),
test_cli(),
test_cli_unroll()
)
ben_c
#> # A tibble: 4 × 6
#> expression min median `itr/sec` mem_alloc `gc/sec`
#> <bch:expr> <bch:tm> <bch:tm> <dbl> <bch:byt> <dbl>
#> 1 test_baseline() 801.26ms 801.26ms 1.25 2.08KB 0
#> 2 test_modulo() 1.17s 1.17s 0.853 2.23KB 0
#> 3 test_cli() 1.14s 1.14s 0.879 174.97KB 0
#> 4 test_cli_unroll() 807.85ms 807.85ms 1.24 3.48KB 0
(ben_c$median[3] - ben_c$median[1]) / 2000000000
#> [1] 1ns
We only update the display a fixed number of times per second. (Currently maximum five times per second.)
Let’s measure how long a single update takes.
cli_progress_bar(total = 100000)
bench::mark(cli_progress_update(force = TRUE), max_iterations = 10000)
#> ■ 0% | ETA: 5m
#> ■ 0% | ETA: 2h
#> ■ 0% | ETA: 1h
#> ■ 0% | ETA: 1h
#> ■ 0% | ETA: 48m
#> ■ 0% | ETA: 41m
#> ■ 0% | ETA: 37m
#> ■ 0% | ETA: 33m
#> ■ 0% | ETA: 31m
#> ■ 0% | ETA: 29m
#> ■ 0% | ETA: 27m
#> ■ 0% | ETA: 26m
#> ■ 0% | ETA: 25m
#> ■ 0% | ETA: 24m
#> ■ 0% | ETA: 23m
#> ■ 0% | ETA: 22m
#> ■ 0% | ETA: 21m
#> ■ 0% | ETA: 20m
#> ■ 0% | ETA: 20m
#> ■ 0% | ETA: 20m
#> ■ 0% | ETA: 19m
#> ■ 0% | ETA: 19m
#> ■ 0% | ETA: 18m
#> ■ 0% | ETA: 18m
#> ■ 0% | ETA: 18m
#> ■ 0% | ETA: 17m
#> ■ 0% | ETA: 17m
#> ■ 0% | ETA: 17m
#> ■ 0% | ETA: 17m
#> ■ 0% | ETA: 16m
#> ■ 0% | ETA: 16m
#> ■ 0% | ETA: 16m
#> ■ 0% | ETA: 16m
#> ■ 0% | ETA: 16m
#> ■ 0% | ETA: 15m
#> ■ 0% | ETA: 15m
#> ■ 0% | ETA: 15m
#> ■ 0% | ETA: 15m
#> ■ 0% | ETA: 15m
#> ■ 0% | ETA: 15m
#> ■ 0% | ETA: 15m
#> ■ 0% | ETA: 15m
#> ■ 0% | ETA: 14m
#> ■ 0% | ETA: 14m
#> ■ 0% | ETA: 14m
#> ■ 0% | ETA: 14m
#> ■ 0% | ETA: 14m
#> ■ 0% | ETA: 14m
#> ■ 0% | ETA: 14m
#> ■ 0% | ETA: 14m
#> ■ 0% | ETA: 14m
#> ■ 0% | ETA: 14m
#> ■ 0% | ETA: 14m
#> ■ 0% | ETA: 14m
#> ■ 0% | ETA: 14m
#> ■ 0% | ETA: 13m
#> ■ 0% | ETA: 13m
#> ■ 0% | ETA: 13m
#> ■ 0% | ETA: 13m
#> ■ 0% | ETA: 13m
#> ■ 0% | ETA: 13m
#> ■ 0% | ETA: 13m
#> ■ 0% | ETA: 13m
#> ■ 0% | ETA: 13m
#> ■ 0% | ETA: 13m
#> ■ 0% | ETA: 13m
#> ■ 0% | ETA: 13m
#> ■ 0% | ETA: 13m
#> ■ 0% | ETA: 13m
#> ■ 0% | ETA: 13m
#> ■ 0% | ETA: 13m
#> ■ 0% | ETA: 13m
#> ■ 0% | ETA: 13m
#> ■ 0% | ETA: 13m
#> ■ 0% | ETA: 13m
#> ■ 0% | ETA: 13m
#> ■ 0% | ETA: 13m
#> ■ 0% | ETA: 13m
#> ■ 0% | ETA: 13m
#> ■ 0% | ETA: 13m
#> ■ 0% | ETA: 12m
#> ■ 0% | ETA: 12m
#> ■ 0% | ETA: 12m
#> # A tibble: 1 × 6
#> expression min median `itr/sec` mem_alloc `gc/sec`
#> <bch:expr> <bch:tm> <bch:> <dbl> <bch:byt> <dbl>
#> 1 cli_progress_update(force = TRUE) 5.26ms 5.72ms 171. 1.43MB 21.1
cli_progress_done()
cli_progress_bar(total = NA)
bench::mark(cli_progress_update(force = TRUE), max_iterations = 10000)
#> ⠙ 1 done (31/s) | 33ms
#> ⠹ 2 done (33/s) | 62ms
#> ⠸ 3 done (44/s) | 68ms
#> ⠼ 4 done (54/s) | 75ms
#> ⠴ 5 done (62/s) | 82ms
#> ⠦ 6 done (69/s) | 88ms
#> ⠧ 7 done (72/s) | 98ms
#> ⠇ 8 done (77/s) | 105ms
#> ⠏ 9 done (82/s) | 111ms
#> ⠋ 10 done (86/s) | 117ms
#> ⠙ 11 done (89/s) | 124ms
#> ⠹ 12 done (92/s) | 131ms
#> ⠸ 13 done (95/s) | 137ms
#> ⠼ 14 done (98/s) | 144ms
#> ⠴ 15 done (98/s) | 154ms
#> ⠦ 16 done (100/s) | 160ms
#> ⠧ 17 done (102/s) | 167ms
#> ⠇ 18 done (104/s) | 173ms
#> ⠏ 19 done (106/s) | 180ms
#> ⠋ 20 done (108/s) | 186ms
#> ⠙ 21 done (109/s) | 193ms
#> ⠹ 22 done (109/s) | 203ms
#> ⠸ 23 done (110/s) | 209ms
#> ⠼ 24 done (112/s) | 216ms
#> ⠴ 25 done (113/s) | 222ms
#> ⠦ 26 done (114/s) | 229ms
#> ⠧ 27 done (115/s) | 236ms
#> ⠇ 28 done (116/s) | 242ms
#> ⠏ 29 done (117/s) | 249ms
#> ⠋ 30 done (116/s) | 259ms
#> ⠙ 31 done (117/s) | 265ms
#> ⠹ 32 done (118/s) | 272ms
#> ⠸ 33 done (119/s) | 278ms
#> ⠼ 34 done (120/s) | 285ms
#> ⠴ 35 done (120/s) | 291ms
#> ⠦ 36 done (121/s) | 298ms
#> ⠧ 37 done (120/s) | 308ms
#> ⠇ 38 done (121/s) | 314ms
#> ⠏ 39 done (122/s) | 321ms
#> ⠋ 40 done (122/s) | 328ms
#> ⠙ 41 done (123/s) | 334ms
#> ⠹ 42 done (124/s) | 340ms
#> ⠸ 43 done (124/s) | 347ms
#> ⠼ 44 done (124/s) | 357ms
#> ⠴ 45 done (124/s) | 363ms
#> ⠦ 46 done (125/s) | 369ms
#> ⠧ 47 done (125/s) | 376ms
#> ⠇ 48 done (126/s) | 382ms
#> ⠏ 49 done (126/s) | 389ms
#> ⠋ 50 done (127/s) | 396ms
#> ⠙ 51 done (127/s) | 402ms
#> ⠹ 52 done (126/s) | 412ms
#> ⠸ 53 done (127/s) | 419ms
#> ⠼ 54 done (127/s) | 425ms
#> ⠴ 55 done (128/s) | 432ms
#> ⠦ 56 done (128/s) | 438ms
#> ⠧ 57 done (128/s) | 445ms
#> ⠇ 58 done (129/s) | 451ms
#> ⠏ 59 done (128/s) | 461ms
#> ⠋ 60 done (128/s) | 468ms
#> ⠙ 61 done (129/s) | 474ms
#> ⠹ 62 done (129/s) | 480ms
#> ⠸ 63 done (130/s) | 487ms
#> ⠼ 64 done (130/s) | 493ms
#> ⠴ 65 done (130/s) | 500ms
#> ⠦ 66 done (130/s) | 509ms
#> ⠧ 67 done (130/s) | 515ms
#> ⠇ 68 done (130/s) | 522ms
#> ⠏ 69 done (131/s) | 528ms
#> ⠋ 70 done (131/s) | 535ms
#> ⠙ 71 done (131/s) | 541ms
#> ⠹ 72 done (132/s) | 548ms
#> ⠸ 73 done (132/s) | 556ms
#> # A tibble: 1 × 6
#> expression min median `itr/sec` mem_alloc `gc/sec`
#> <bch:expr> <bch:tm> <bch:> <dbl> <bch:byt> <dbl>
#> 1 cli_progress_update(force = TRUE) 6.03ms 6.5ms 153. 278KB 24.7
cli_progress_done()