cli progress bar benchmark
Gábor Csárdi
2023-11-14
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 62519221. 0B 0
#> 2 fun() 129.92ns 160.1ns 4422941. 0B 0
#> 3 .Call(ccli_tick_reset) 120.02ns 131.1ns 7230596. 0B 0
#> 4 interactive() 8.96ns 11.1ns 66493333. 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 51.1ns 17321472. 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 5912968. 0B 0
#> 2 ta[[1]] 140ns 161ns 5400302. 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() 13.9ms 13.9ms 71.8 25.2KB 2010.
#> 2 fp() 16.4ms 16.4ms 61.0 83.3KB 1525.
(ben_taf$median[2] - ben_taf$median[1]) / 1e5
#> [1] 24.6ns
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) 152ms 167ms 5.48 0B 53.0
#> 2 fp(1e+06) 179ms 181ms 5.50 1.88KB 53.2
(ben_taf2$median[2] - ben_taf2$median[1]) / 1e6
#> [1] 13.6ns
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.54s 1.54s 0.650 0B 39.0
#> 2 fp(1e+07) 1.69s 1.69s 0.593 1.88KB 32.0
(ben_taf3$median[2] - ben_taf3$median[1]) / 1e7
#> [1] 14.6ns
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) 15.4s 15.4s 0.0651 0B 40.7
#> 2 fp(1e+08) 17.4s 17.4s 0.0575 1.88KB 34.6
(ben_taf4$median[2] - ben_taf4$median[1]) / 1e8
#> [1] 20.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() 70.1ms 78ms 9.46 781KB 15.1
#> 2 f01() 88.8ms 105ms 9.87 781KB 16.4
#> 3 fp() 100ms 130ms 7.35 783KB 9.18
(ben_tam$median[3] - ben_tam$median[1]) / 1e5
#> [1] 523ns
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) 845.1ms 845.1ms 1.18 7.63MB 8.28
#> 2 f01(1e+06) 1.24s 1.24s 0.809 7.63MB 6.48
#> 3 fp(1e+06) 1.39s 1.39s 0.718 7.63MB 5.74
(ben_tam2$median[3] - ben_tam2$median[1]) / 1e6
#> [1] 548ns
(ben_tam2$median[3] - ben_tam2$median[2]) / 1e6
#> [1] 158ns
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() 69.8ms 74.5ms 13.1 884KB 7.51
#> 2 f01() 100.1ms 110.7ms 8.14 781KB 8.14
#> 3 fp() 116.6ms 124.7ms 7.99 783KB 5.99
(ben_pur$median[3] - ben_pur$median[1]) / 1e5
#> [1] 501ns
(ben_pur$median[3] - ben_pur$median[2]) / 1e5
#> [1] 139ns
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) 802.98ms 802.98ms 1.25 7.63MB 2.49
#> 2 f01(1e+06) 903.29ms 903.29ms 1.11 7.63MB 2.21
#> 3 fp(1e+06) 1.03s 1.03s 0.973 7.63MB 2.92
(ben_pur2$median[3] - ben_pur2$median[1]) / 1e6
#> [1] 225ns
(ben_pur2$median[3] - ben_pur2$median[2]) / 1e6
#> [1] 124ns
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() 14.74ms 14.93ms 65.3 40.3KB 1.98
#> 2 fp() 4.07s 4.07s 0.246 100.8KB 1.96
(ben_tk$median[2] - ben_tk$median[1]) / 1e5
#> [1] 40.6µ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() 12.48ms 12.59ms 71.5 19.9KB 5.96
#> 2 ff() 19.19ms 19.5ms 47.2 28.6KB 1.97
#> 3 fp() 2.22s 2.22s 0.451 26.1KB 2.25
(ben_api$median[3] - ben_api$median[1]) / 1e5
#> [1] 22.1µs
(ben_api$median[2] - ben_api$median[1]) / 1e5
#> [1] 69.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) 130.9ms 142.6ms 6.96 0B 5.22
#> 2 ff(1e+06) 206.5ms 209.6ms 4.78 1.88KB 4.78
#> 3 fp(1e+06) 23.3s 23.3s 0.0430 1.88KB 1.85
(ben_api2$median[3] - ben_api2$median[1]) / 1e6
#> [1] 23.1µs
(ben_api2$median[2] - ben_api2$median[1]) / 1e6
#> [1] 67ns
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() 619.77ms 619.77ms 1.61 2.08KB 0
#> 2 test_modulo() 1.25s 1.25s 0.801 2.24KB 0
#> 3 test_cli() 1.26s 1.26s 0.792 23.7KB 0
#> 4 test_cli_unroll() 632.02ms 632.02ms 1.58 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: 5m
#> ■ 0% | ETA: 2h
#> ■ 0% | ETA: 1h
#> ■ 0% | ETA: 1h
#> ■ 0% | ETA: 1h
#> ■ 0% | ETA: 45m
#> ■ 0% | ETA: 40m
#> ■ 0% | ETA: 36m
#> ■ 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: 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: 17m
#> ■ 0% | ETA: 16m
#> ■ 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: 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: 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
#> # 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 = T… 5.7ms 5.97ms 165. 1.35MB 2.04
cli_progress_done()
Iterator without a bar
cli_progress_bar(total = NA)
bench::mark(cli_progress_update(force = TRUE), max_iterations = 10000)
#> ⠙ 1 done (400/s) | 3ms
#> ⠹ 2 done (69/s) | 29ms
#> ⠸ 3 done (83/s) | 37ms
#> ⠼ 4 done (92/s) | 44ms
#> ⠴ 5 done (99/s) | 51ms
#> ⠦ 6 done (104/s) | 58ms
#> ⠧ 7 done (108/s) | 65ms
#> ⠇ 8 done (111/s) | 73ms
#> ⠏ 9 done (114/s) | 80ms
#> ⠋ 10 done (116/s) | 87ms
#> ⠙ 11 done (118/s) | 94ms
#> ⠹ 12 done (119/s) | 101ms
#> ⠸ 13 done (121/s) | 108ms
#> ⠼ 14 done (122/s) | 116ms
#> ⠴ 15 done (123/s) | 123ms
#> ⠦ 16 done (124/s) | 130ms
#> ⠧ 17 done (125/s) | 137ms
#> ⠇ 18 done (126/s) | 144ms
#> ⠏ 19 done (126/s) | 151ms
#> ⠋ 20 done (127/s) | 158ms
#> ⠙ 21 done (128/s) | 165ms
#> ⠹ 22 done (128/s) | 172ms
#> ⠸ 23 done (128/s) | 180ms
#> ⠼ 24 done (129/s) | 187ms
#> ⠴ 25 done (130/s) | 194ms
#> ⠦ 26 done (130/s) | 201ms
#> ⠧ 27 done (130/s) | 208ms
#> ⠇ 28 done (131/s) | 215ms
#> ⠏ 29 done (131/s) | 222ms
#> ⠋ 30 done (132/s) | 229ms
#> ⠙ 31 done (132/s) | 236ms
#> ⠹ 32 done (132/s) | 243ms
#> ⠸ 33 done (133/s) | 249ms
#> ⠼ 34 done (133/s) | 256ms
#> ⠴ 35 done (133/s) | 263ms
#> ⠦ 36 done (134/s) | 270ms
#> ⠧ 37 done (134/s) | 277ms
#> ⠇ 38 done (134/s) | 284ms
#> ⠏ 39 done (134/s) | 291ms
#> ⠋ 40 done (134/s) | 298ms
#> ⠙ 41 done (135/s) | 305ms
#> ⠹ 42 done (135/s) | 312ms
#> ⠸ 43 done (135/s) | 319ms
#> ⠼ 44 done (135/s) | 326ms
#> ⠴ 45 done (135/s) | 333ms
#> ⠦ 46 done (133/s) | 345ms
#> ⠧ 47 done (134/s) | 352ms
#> ⠇ 48 done (134/s) | 360ms
#> ⠏ 49 done (134/s) | 367ms
#> ⠋ 50 done (134/s) | 374ms
#> ⠙ 51 done (134/s) | 381ms
#> ⠹ 52 done (134/s) | 388ms
#> ⠸ 53 done (134/s) | 395ms
#> ⠼ 54 done (135/s) | 402ms
#> ⠴ 55 done (135/s) | 409ms
#> ⠦ 56 done (135/s) | 416ms
#> ⠧ 57 done (135/s) | 423ms
#> ⠇ 58 done (135/s) | 430ms
#> ⠏ 59 done (135/s) | 437ms
#> ⠋ 60 done (135/s) | 444ms
#> ⠙ 61 done (135/s) | 451ms
#> ⠹ 62 done (136/s) | 458ms
#> ⠸ 63 done (136/s) | 465ms
#> ⠼ 64 done (136/s) | 472ms
#> ⠴ 65 done (136/s) | 479ms
#> ⠦ 66 done (136/s) | 486ms
#> ⠧ 67 done (136/s) | 493ms
#> ⠇ 68 done (136/s) | 500ms
#> ⠏ 69 done (136/s) | 507ms
#> ⠋ 70 done (136/s) | 514ms
#> ⠙ 71 done (137/s) | 521ms
#> ⠹ 72 done (137/s) | 528ms
#> # 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.81ms 7.03ms 142. 198KB 2.03
cli_progress_done()