cli progress bar benchmark
Gábor Csárdi
2023-01-09
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 0 0 1582887653. 0B 0
#> 2 fun() 99.9ns 200ns 3294497. 0B 0
#> 3 .Call(ccli_tick_reset) 99.9ns 200ns 5362941. 0B 0
#> 4 interactive() 0 0 803371233. 0B 0
ben_st2 <- bench::mark(
if (`__cli_update_due`) foobar()
)
ben_st2
#> # A tibble: 1 × 6
#> expression min median itr/s…¹ mem_a…² gc/se…³
#> <bch:expr> <bch:tm> <bch:> <dbl> <bch:b> <dbl>
#> 1 if (`__cli_update_due`) foobar() 0 100ns 1.23e7 0B 0
#> # … with abbreviated variable names ¹`itr/sec`, ²mem_alloc, ³`gc/sec`
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]] 99.9ns 200ns 4811252. 0B 0
#> 2 ta[[1]] 99.9ns 200ns 4223237. 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() 21.7ms 21.7ms 46.1 25.2KB 785.
#> 2 fp() 28ms 28ms 35.7 83.2KB 571.
(ben_taf$median[2] - ben_taf$median[1]) / 1e5
#> [1] 63.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) 264ms 269ms 3.72 0B 35.3
#> 2 fp(1e+06) 270ms 275ms 3.64 1.85KB 34.6
(ben_taf2$median[2] - ben_taf2$median[1]) / 1e6
#> [1] 5.5ns
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) 2.46s 2.46s 0.406 0B 38.9
#> 2 fp(1e+07) 2.69s 2.69s 0.372 1.85KB 34.6
(ben_taf3$median[2] - ben_taf3$median[1]) / 1e7
#> [1] 22.4ns
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) 23.2s 23.2s 0.0432 0B 25.4
#> 2 fp(1e+08) 25.4s 25.4s 0.0394 1.85KB 22.4
(ben_taf4$median[2] - ben_taf4$median[1]) / 1e8
#> [1] 22.1ns
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() 115ms 138ms 7.31 781KB 20.1
#> 2 f01() 195ms 208ms 4.26 781KB 9.94
#> 3 fp() 126ms 144ms 7.12 783KB 12.5
(ben_tam$median[3] - ben_tam$median[1]) / 1e5
#> [1] 59.8ns
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) 1.38s 1.38s 0.725 7.63MB 5.80
#> 2 f01(1e+06) 2.38s 2.38s 0.420 7.63MB 3.36
#> 3 fp(1e+06) 3.26s 3.26s 0.307 7.63MB 2.45
(ben_tam2$median[3] - ben_tam2$median[1]) / 1e6
#> [1] 1.88µs
(ben_tam2$median[3] - ben_tam2$median[2]) / 1e6
#> [1] 880ns
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())
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() 91ms 98.1ms 10.2 870KB 2.55
#> 2 f01() 102ms 105.2ms 9.41 781KB 6.28
#> 3 fp() 104ms 109.2ms 9.10 783KB 2.28
(ben_pur$median[3] - ben_pur$median[1]) / 1e5
#> [1] 111ns
(ben_pur$median[3] - ben_pur$median[2]) / 1e5
#> [1] 39.4ns
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) 1.12s 1.12s 0.895 7.63MB 1.79
#> 2 f01(1e+06) 1.29s 1.29s 0.775 7.63MB 1.55
#> 3 fp(1e+06) 1.44s 1.44s 0.696 7.63MB 2.09
(ben_pur2$median[3] - ben_pur2$median[1]) / 1e6
#> [1] 319ns
(ben_pur2$median[3] - ben_pur2$median[2]) / 1e6
#> [1] 146ns
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() 21.58ms 22.48ms 44.2 40.3KB 1.92
#> 2 fp() 5.67s 5.67s 0.176 100.8KB 1.41
(ben_tk$median[2] - ben_tk$median[1]) / 1e5
#> [1] 56.5µ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() 19.5ms 19.58ms 46.9 19.9KB 3.91
#> 2 ff() 28.68ms 29ms 32.7 28.6KB 1.92
#> 3 fp() 2.94s 2.94s 0.340 26KB 1.36
(ben_api$median[3] - ben_api$median[1]) / 1e5
#> [1] 29.2µs
(ben_api$median[2] - ben_api$median[1]) / 1e5
#> [1] 94.2ns
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) 219.8ms 228ms 4.39 0B 4.39
#> 2 ff(1e+06) 301.5ms 310.9ms 3.22 1.85KB 1.61
#> 3 fp(1e+06) 32.4s 32.4s 0.0308 1.85KB 1.29
(ben_api2$median[3] - ben_api2$median[1]) / 1e6
#> [1] 32.2µs
(ben_api2$median[2] - ben_api2$median[1]) / 1e6
#> [1] 82.9ns
C benchmarks
Baseline function:
() {
SEXP test_baselineint i;
int res = 0;
for (i = 0; i < 2000000000; i++) {
+= i % 2;
res }
return ScalarInteger(res);
}
Switch + modulo check:
(SEXP progress) {
SEXP test_moduloint 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);
+= i % 2;
res }
return ScalarInteger(res);
}
cli progress bar API:
() {
SEXP test_cliint i;
int res = 0;
= PROTECT(cli_progress_bar(2000000000, NULL));
SEXP bar for (i = 0; i < 2000000000; i++) {
if (CLI_SHOULD_TICK) cli_progress_set(bar, i);
+= i % 2;
res }
(bar);
cli_progress_done(1);
UNPROTECTreturn ScalarInteger(res);
}
() {
SEXP test_cli_unrollint i = 0;
int res = 0;
= PROTECT(cli_progress_bar(2000000000, NULL));
SEXP bar int s, final, step = 2000000000 / 100000;
for (s = 0; s < 100000; s++) {
if (CLI_SHOULD_TICK) cli_progress_set(bar, i);
= (s + 1) * step;
final for (i = s * step; i < final; i++) {
+= i % 2;
res }
}
(bar);
cli_progress_done(1);
UNPROTECTreturn 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() 1s 1s 0.995 2.08KB 0
#> 2 test_modulo() 2.05s 2.05s 0.488 2.24KB 0
#> 3 test_cli() 1.61s 1.61s 0.622 23.69KB 0
#> 4 test_cli_unroll() 1.02s 1.02s 0.981 3.35KB 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: 8m
#> ■ 0% | ETA: 3h
#> ■ 0% | ETA: 2h
#> ■ 0% | ETA: 2h
#> ■ 0% | ETA: 1h
#> ■ 0% | ETA: 1h
#> ■ 0% | ETA: 1h
#> ■ 0% | ETA: 1h
#> ■ 0% | ETA: 49m
#> ■ 0% | ETA: 46m
#> ■ 0% | ETA: 43m
#> ■ 0% | ETA: 41m
#> ■ 0% | ETA: 39m
#> ■ 0% | ETA: 37m
#> ■ 0% | ETA: 36m
#> ■ 0% | ETA: 34m
#> ■ 0% | ETA: 33m
#> ■ 0% | ETA: 32m
#> ■ 0% | ETA: 31m
#> ■ 0% | ETA: 30m
#> ■ 0% | ETA: 30m
#> ■ 0% | ETA: 29m
#> ■ 0% | ETA: 28m
#> ■ 0% | ETA: 28m
#> ■ 0% | ETA: 27m
#> ■ 0% | ETA: 27m
#> ■ 0% | ETA: 26m
#> ■ 0% | ETA: 26m
#> ■ 0% | ETA: 26m
#> ■ 0% | ETA: 25m
#> ■ 0% | ETA: 25m
#> ■ 0% | ETA: 25m
#> ■ 0% | ETA: 25m
#> ■ 0% | ETA: 24m
#> ■ 0% | ETA: 24m
#> ■ 0% | ETA: 24m
#> ■ 0% | ETA: 24m
#> ■ 0% | ETA: 23m
#> ■ 0% | ETA: 23m
#> ■ 0% | ETA: 23m
#> ■ 0% | ETA: 23m
#> ■ 0% | ETA: 23m
#> ■ 0% | ETA: 23m
#> ■ 0% | ETA: 22m
#> ■ 0% | ETA: 22m
#> ■ 0% | ETA: 22m
#> ■ 0% | ETA: 22m
#> ■ 0% | ETA: 22m
#> ■ 0% | ETA: 22m
#> ■ 0% | ETA: 21m
#> ■ 0% | ETA: 21m
#> ■ 0% | ETA: 21m
#> ■ 0% | ETA: 21m
#> ■ 0% | ETA: 21m
#> ■ 0% | ETA: 21m
#> # A tibble: 1 × 6
#> expression min median itr/s…¹ mem_a…² gc/se…³
#> <bch:expr> <bch:t> <bch:> <dbl> <bch:b> <dbl>
#> 1 cli_progress_update(force = TRUE) 8.89ms 9.04ms 108. 1.28MB 2.04
#> # … with abbreviated variable names ¹`itr/sec`, ²mem_alloc, ³`gc/sec`
cli_progress_done()
Iterator without a bar
cli_progress_bar(total = NA)
bench::mark(cli_progress_update(force = TRUE), max_iterations = 10000)
#> ⠙ 1 done (270/s) | 4ms
#> ⠹ 2 done (44/s) | 46ms
#> ⠸ 3 done (53/s) | 57ms
#> ⠼ 4 done (60/s) | 68ms
#> ⠴ 5 done (64/s) | 79ms
#> ⠦ 6 done (68/s) | 89ms
#> ⠧ 7 done (70/s) | 100ms
#> ⠇ 8 done (73/s) | 111ms
#> ⠏ 9 done (74/s) | 122ms
#> ⠋ 10 done (76/s) | 132ms
#> ⠙ 11 done (77/s) | 143ms
#> ⠹ 12 done (79/s) | 153ms
#> ⠸ 13 done (80/s) | 164ms
#> ⠼ 14 done (80/s) | 175ms
#> ⠴ 15 done (81/s) | 185ms
#> ⠦ 16 done (82/s) | 196ms
#> ⠧ 17 done (82/s) | 207ms
#> ⠇ 18 done (83/s) | 218ms
#> ⠏ 19 done (83/s) | 229ms
#> ⠋ 20 done (84/s) | 240ms
#> ⠙ 21 done (84/s) | 251ms
#> ⠹ 22 done (84/s) | 261ms
#> ⠸ 23 done (85/s) | 273ms
#> ⠼ 24 done (85/s) | 283ms
#> ⠴ 25 done (85/s) | 295ms
#> ⠦ 26 done (85/s) | 306ms
#> ⠧ 27 done (85/s) | 317ms
#> ⠇ 28 done (86/s) | 328ms
#> ⠏ 29 done (86/s) | 339ms
#> ⠋ 30 done (86/s) | 350ms
#> ⠙ 31 done (86/s) | 361ms
#> ⠹ 32 done (86/s) | 372ms
#> ⠸ 33 done (86/s) | 383ms
#> ⠼ 34 done (86/s) | 394ms
#> ⠴ 35 done (86/s) | 405ms
#> ⠦ 36 done (87/s) | 417ms
#> ⠧ 37 done (87/s) | 428ms
#> ⠇ 38 done (87/s) | 439ms
#> ⠏ 39 done (87/s) | 450ms
#> ⠋ 40 done (87/s) | 461ms
#> ⠙ 41 done (87/s) | 472ms
#> ⠹ 42 done (87/s) | 483ms
#> ⠸ 43 done (87/s) | 494ms
#> ⠼ 44 done (87/s) | 505ms
#> ⠴ 45 done (87/s) | 516ms
#> ⠦ 46 done (87/s) | 527ms
#> ⠧ 47 done (87/s) | 538ms
#> # A tibble: 1 × 6
#> expression min median itr/s…¹ mem_a…² gc/se…³
#> <bch:expr> <bch:t> <bch:> <dbl> <bch:b> <dbl>
#> 1 cli_progress_update(force = TRUE) 10.5ms 10.9ms 91.7 202KB 0
#> # … with abbreviated variable names ¹`itr/sec`, ²mem_alloc, ³`gc/sec`
cli_progress_done()