cli progress bar benchmark
Gábor Csárdi
2024-06-23
Source:vignettes/progress-benchmark.Rmd
progress-benchmark.Rmd
Introduction
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
R benchmarks
The timer
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 8.96ns 20ns 50465381. 0B 0
#> 2 fun() 140.05ns 160ns 4527363. 0B 0
#> 3 .Call(ccli_tick_reset) 110.01ns 130ns 7146685. 0B 0
#> 4 interactive() 8.96ns 20ns 56501873. 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> <bch:> <dbl> <bch:byt> <dbl>
#> 1 if (`__cli_update_due`) fooba… 40ns 50.1ns 19111554. 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]] 140ns 151ns 6029526. 0B 0
#> 2 ta[[1]] 160ns 180ns 5297671. 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() 11.9ms 11.9ms 81.7 25.1KB 871.
#> 2 fp() 13.5ms 13.6ms 73.4 83.1KB 1064.
(ben_taf$median[2] - ben_taf$median[1]) / 1e5
#> [1] 17.5ns
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) 134ms 142ms 6.53 0B 60.4
#> 2 fp(1e+06) 147ms 148ms 6.75 1.82KB 60.7
(ben_taf2$median[2] - ben_taf2$median[1]) / 1e6
#> [1] 6.66ns
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.34s 1.34s 0.745 0B 39.5
#> 2 fp(1e+07) 1.47s 1.47s 0.680 1.82KB 36.7
(ben_taf3$median[2] - ben_taf3$median[1]) / 1e7
#> [1] 12.8ns
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) 13.8s 13.8s 0.0726 0B 44.2
#> 2 fp(1e+08) 14.8s 14.8s 0.0675 1.82KB 39.2
(ben_taf4$median[2] - ben_taf4$median[1]) / 1e8
#> [1] 10.3ns
Mapping with 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() 73.9ms 80.9ms 12.0 781KB 13.7
#> 2 f01() 103.6ms 106.2ms 8.18 781KB 16.4
#> 3 fp() 123.1ms 132.1ms 7.63 783KB 11.4
(ben_tam$median[3] - ben_tam$median[1]) / 1e5
#> [1] 512ns
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) 814.12ms 814.12ms 1.23 7.63MB 8.60
#> 2 f01(1e+06) 1.23s 1.23s 0.813 7.63MB 6.50
#> 3 fp(1e+06) 1.86s 1.86s 0.539 7.63MB 4.31
(ben_tam2$median[3] - ben_tam2$median[1]) / 1e6
#> [1] 1.04µs
(ben_tam2$median[3] - ben_tam2$median[2]) / 1e6
#> [1] 626ns
Mapping with purrr
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())
#> Warning: Some expressions had a GC in every iteration; so filtering is
#> disabled.
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() 67.4ms 74.6ms 13.1 884KB 9.33
#> 2 f01() 100.6ms 120.8ms 8.06 781KB 8.06
#> 3 fp() 118.1ms 124.9ms 7.99 783KB 6.00
(ben_pur$median[3] - ben_pur$median[1]) / 1e5
#> [1] 503ns
(ben_pur$median[3] - ben_pur$median[2]) / 1e5
#> [1] 41.7ns
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) 756.16ms 756.16ms 1.32 7.63MB 2.64
#> 2 f01(1e+06) 964.76ms 964.76ms 1.04 7.63MB 2.07
#> 3 fp(1e+06) 1.11s 1.11s 0.898 7.63MB 2.69
(ben_pur2$median[3] - ben_pur2$median[1]) / 1e6
#> [1] 357ns
(ben_pur2$median[3] - ben_pur2$median[2]) / 1e6
#> [1] 149ns
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() 12.74ms 12.86ms 75.6 40.2KB 3.98
#> 2 fp() 3.88s 3.88s 0.258 100.6KB 2.06
(ben_tk$median[2] - ben_tk$median[1]) / 1e5
#> [1] 38.7µs
Traditional API
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() 11.7ms 11.86ms 68.0 19.9KB 5.66
#> 2 ff() 22.56ms 23.05ms 40.0 28.5KB 2.00
#> 3 fp() 2.19s 2.19s 0.458 25.9KB 1.83
(ben_api$median[3] - ben_api$median[1]) / 1e5
#> [1] 21.7µs
(ben_api$median[2] - ben_api$median[1]) / 1e5
#> [1] 112ns
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) 133.4ms 140.8ms 7.08 0B 5.31
#> 2 ff(1e+06) 244.9ms 250ms 4.00 1.82KB 2.00
#> 3 fp(1e+06) 22.5s 22.5s 0.0444 1.82KB 1.82
(ben_api2$median[3] - ben_api2$median[1]) / 1e6
#> [1] 22.4µs
(ben_api2$median[2] - ben_api2$median[1]) / 1e6
#> [1] 109ns
C benchmarks
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() 619.54ms 619.54ms 1.61 2.08KB 0
#> 2 test_modulo() 1.24s 1.24s 0.806 2.23KB 0
#> 3 test_cli() 1.24s 1.24s 0.807 23.91KB 0
#> 4 test_cli_unroll() 620.25ms 620.25ms 1.61 3.59KB 0
(ben_c$median[3] - ben_c$median[1]) / 2000000000
#> [1] 1ns
Display update
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.
Iterator with a bar
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: 50m
#> ■ 0% | ETA: 43m
#> ■ 0% | ETA: 38m
#> ■ 0% | ETA: 35m
#> ■ 0% | ETA: 32m
#> ■ 0% | ETA: 30m
#> ■ 0% | ETA: 28m
#> ■ 0% | ETA: 26m
#> ■ 0% | ETA: 25m
#> ■ 0% | ETA: 24m
#> ■ 0% | ETA: 23m
#> ■ 0% | ETA: 22m
#> ■ 0% | ETA: 21m
#> ■ 0% | ETA: 21m
#> ■ 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: 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: 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: 12m
#> ■ 0% | ETA: 12m
#> ■ 0% | ETA: 12m
#> ■ 0% | ETA: 12m
#> ■ 0% | ETA: 12m
#> ■ 0% | ETA: 12m
#> ■ 0% | ETA: 12m
#> ■ 0% | ETA: 12m
#> ■ 0% | ETA: 12m
#> ■ 0% | ETA: 12m
#> ■ 0% | ETA: 12m
#> ■ 0% | ETA: 12m
#> ■ 0% | ETA: 12m
#> ■ 0% | ETA: 12m
#> ■ 0% | ETA: 12m
#> ■ 0% | ETA: 12m
#> ■ 0% | ETA: 12m
#> ■ 0% | ETA: 12m
#> ■ 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:> <bch:> <dbl> <bch:byt> <dbl>
#> 1 cli_progress_update(force = … 5.61ms 5.67ms 173. 1.34MB 0
Iterator without a bar
cli_progress_bar(total = NA)
bench::mark(cli_progress_update(force = TRUE), max_iterations = 10000)
#> ⠙ 1 done (429/s) | 3ms
#> ⠹ 2 done (74/s) | 28ms
#> ⠸ 3 done (89/s) | 34ms
#> ⠼ 4 done (99/s) | 41ms
#> ⠴ 5 done (107/s) | 47ms
#> ⠦ 6 done (112/s) | 54ms
#> ⠧ 7 done (116/s) | 61ms
#> ⠇ 8 done (120/s) | 67ms
#> ⠏ 9 done (123/s) | 74ms
#> ⠋ 10 done (125/s) | 81ms
#> ⠙ 11 done (127/s) | 87ms
#> ⠹ 12 done (129/s) | 94ms
#> ⠸ 13 done (130/s) | 100ms
#> ⠼ 14 done (132/s) | 107ms
#> ⠴ 15 done (133/s) | 114ms
#> ⠦ 16 done (134/s) | 120ms
#> ⠧ 17 done (135/s) | 127ms
#> ⠇ 18 done (136/s) | 133ms
#> ⠏ 19 done (136/s) | 140ms
#> ⠋ 20 done (137/s) | 147ms
#> ⠙ 21 done (137/s) | 153ms
#> ⠹ 22 done (138/s) | 160ms
#> ⠸ 23 done (138/s) | 167ms
#> ⠼ 24 done (139/s) | 173ms
#> ⠴ 25 done (139/s) | 180ms
#> ⠦ 26 done (140/s) | 187ms
#> ⠧ 27 done (140/s) | 193ms
#> ⠇ 28 done (140/s) | 200ms
#> ⠏ 29 done (141/s) | 207ms
#> ⠋ 30 done (141/s) | 213ms
#> ⠙ 31 done (141/s) | 220ms
#> ⠹ 32 done (142/s) | 227ms
#> ⠸ 33 done (142/s) | 233ms
#> ⠼ 34 done (142/s) | 240ms
#> ⠴ 35 done (142/s) | 246ms
#> ⠦ 36 done (143/s) | 253ms
#> ⠧ 37 done (143/s) | 260ms
#> ⠇ 38 done (143/s) | 267ms
#> ⠏ 39 done (143/s) | 273ms
#> ⠋ 40 done (143/s) | 280ms
#> ⠙ 41 done (143/s) | 287ms
#> ⠹ 42 done (144/s) | 293ms
#> ⠸ 43 done (144/s) | 300ms
#> ⠼ 44 done (144/s) | 307ms
#> ⠴ 45 done (144/s) | 313ms
#> ⠦ 46 done (144/s) | 320ms
#> ⠧ 47 done (144/s) | 326ms
#> ⠇ 48 done (144/s) | 333ms
#> ⠏ 49 done (144/s) | 340ms
#> ⠋ 50 done (145/s) | 346ms
#> ⠙ 51 done (145/s) | 353ms
#> ⠹ 52 done (145/s) | 360ms
#> ⠸ 53 done (145/s) | 366ms
#> ⠼ 54 done (145/s) | 373ms
#> ⠴ 55 done (145/s) | 380ms
#> ⠦ 56 done (145/s) | 386ms
#> ⠧ 57 done (145/s) | 393ms
#> ⠇ 58 done (145/s) | 399ms
#> ⠏ 59 done (146/s) | 406ms
#> ⠋ 60 done (146/s) | 413ms
#> ⠙ 61 done (146/s) | 419ms
#> ⠹ 62 done (146/s) | 426ms
#> ⠸ 63 done (146/s) | 433ms
#> ⠼ 64 done (146/s) | 439ms
#> ⠴ 65 done (146/s) | 446ms
#> ⠦ 66 done (146/s) | 453ms
#> ⠧ 67 done (146/s) | 459ms
#> ⠇ 68 done (146/s) | 466ms
#> ⠏ 69 done (146/s) | 473ms
#> ⠋ 70 done (146/s) | 479ms
#> ⠙ 71 done (146/s) | 486ms
#> ⠹ 72 done (146/s) | 493ms
#> ⠸ 73 done (146/s) | 499ms
#> ⠼ 74 done (146/s) | 506ms
#> ⠴ 75 done (146/s) | 513ms
#> ⠦ 76 done (146/s) | 519ms
#> ⠧ 77 done (147/s) | 526ms
#> # A tibble: 1 × 6
#> expression min median `itr/sec` mem_alloc `gc/sec`
#> <bch:expr> <bch:> <bch:> <dbl> <bch:byt> <dbl>
#> 1 cli_progress_update(force = … 6.51ms 6.62ms 151. 198KB 0