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 6.87ns 10.9ns 76026607. 0B 0
#> 2 fun() 96.04ns 105ns 5760871. 0B 0
#> 3 .Call(ccli_tick_reset) 91.04ns 100ns 9104102. 0B 0
#> 4 interactive() 10.94ns 15.9ns 55495445. 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() 38.9ns 44.9ns 21420071. 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]] 95.9ns 102ns 7856876. 0B 0
#> 2 ta[[1]] 105.1ns 113ns 7191032. 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.88ms 9.64ms 103. 21.6KB 427.
#> 2 fp() 9.98ms 10.2ms 97.3 82.3KB 445.
(ben_taf$median[2] - ben_taf$median[1]) / 1e5
#> [1] 5.54ns
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) 105ms 106ms 7.63 0B 63.0
#> 2 fp(1e+06) 107ms 116ms 8.71 1.88KB 69.6
(ben_taf2$median[2] - ben_taf2$median[1]) / 1e6
#> [1] 9.53ns
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.15s 1.15s 0.868 0B 72.1
#> 2 fp(1e+07) 1.22s 1.22s 0.818 1.88KB 67.1
(ben_taf3$median[2] - ben_taf3$median[1]) / 1e7
#> [1] 7.04ns
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.2s 11.2s 0.0897 0B 46.8
#> 2 fp(1e+08) 13.5s 13.5s 0.0740 1.88KB 36.5
(ben_taf4$median[2] - ben_taf4$median[1]) / 1e8
#> [1] 23.6ns
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.5ms 76.8ms 9.67 781KB 19.3
#> 2 f01() 78.9ms 87.4ms 11.5 781KB 19.1
#> 3 fp() 102ms 122.4ms 7.55 783KB 10.6
(ben_tam$median[3] - ben_tam$median[1]) / 1e5
#> [1] 456ns
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) 680.45ms 680.45ms 1.47 7.63MB 4.41
#> 2 f01(1e+06) 964.99ms 964.99ms 1.04 7.63MB 6.22
#> 3 fp(1e+06) 1.26s 1.26s 0.793 7.63MB 3.96
(ben_tam2$median[3] - ben_tam2$median[1]) / 1e6
#> [1] 581ns
(ben_tam2$median[3] - ben_tam2$median[2]) / 1e6
#> [1] 296ns
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.9ms 56.1ms 17.4 1.39MB 10.4
#> 2 f01() 66.6ms 76.1ms 13.3 781.3KB 9.98
#> 3 fp() 65.7ms 66.3ms 14.2 783.24KB 14.2
(ben_pur$median[3] - ben_pur$median[1]) / 1e5
#> [1] 102ns
(ben_pur$median[3] - ben_pur$median[2]) / 1e5
#> [1] 1ns
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) 692.4ms 692.4ms 1.44 7.63MB 2.89
#> 2 f01(1e+06) 895.01ms 895.01ms 1.12 7.63MB 2.23
#> 3 fp(1e+06) 1.04s 1.04s 0.958 7.63MB 3.83
(ben_pur2$median[3] - ben_pur2$median[1]) / 1e6
#> [1] 351ns
(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() 8.48ms 8.84ms 107. 39.3KB 5.96
#> 2 fp() 3.44s 3.44s 0.290 100.4KB 2.32
(ben_tk$median[2] - ben_tk$median[1]) / 1e5
#> [1] 34.3µ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.67ms 9.17ms 83.6 18.7KB 7.96
#> 2 ff() 15.41ms 16.37ms 53.2 27.6KB 3.94
#> 3 fp() 2.01s 2.01s 0.498 25.1KB 1.99
(ben_api$median[3] - ben_api$median[1]) / 1e5
#> [1] 20µs
(ben_api$median[2] - ben_api$median[1]) / 1e5
#> [1] 72.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) 102ms 119.4ms 8.69 0B 6.95
#> 2 ff(1e+06) 159.3ms 185.1ms 5.65 1.9KB 5.65
#> 3 fp(1e+06) 18.1s 18.1s 0.0551 1.9KB 2.53
(ben_api2$median[3] - ben_api2$median[1]) / 1e6
#> [1] 18µs
(ben_api2$median[2] - ben_api2$median[1]) / 1e6
#> [1] 65.7ns
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() 832.74ms 832.74ms 1.20 2.08KB 0
#> 2 test_modulo() 1.22s 1.22s 0.819 2.23KB 0
#> 3 test_cli() 1.18s 1.18s 0.849 174.97KB 0
#> 4 test_cli_unroll() 824.26ms 824.26ms 1.21 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: 49m
#> ■ 0% | ETA: 43m
#> ■ 0% | ETA: 38m
#> ■ 0% | ETA: 34m
#> ■ 0% | ETA: 32m
#> ■ 0% | ETA: 30m
#> ■ 0% | ETA: 28m
#> ■ 0% | ETA: 27m
#> ■ 0% | ETA: 25m
#> ■ 0% | ETA: 24m
#> ■ 0% | ETA: 23m
#> ■ 0% | ETA: 22m
#> ■ 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: 17m
#> ■ 0% | ETA: 16m
#> ■ 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: 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: 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
#> # 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.42ms 5.89ms 168. 1.43MB 24.7
cli_progress_done()
cli_progress_bar(total = NA)
bench::mark(cli_progress_update(force = TRUE), max_iterations = 10000)
#> ⠙ 1 done (484/s) | 3ms
#> ⠹ 2 done (67/s) | 31ms
#> ⠸ 3 done (81/s) | 38ms
#> ⠼ 4 done (53/s) | 76ms
#> ⠴ 5 done (61/s) | 83ms
#> ⠦ 6 done (67/s) | 90ms
#> ⠧ 7 done (73/s) | 96ms
#> ⠇ 8 done (78/s) | 103ms
#> ⠏ 9 done (82/s) | 110ms
#> ⠋ 10 done (86/s) | 117ms
#> ⠙ 11 done (90/s) | 123ms
#> ⠹ 12 done (90/s) | 133ms
#> ⠸ 13 done (93/s) | 140ms
#> ⠼ 14 done (96/s) | 147ms
#> ⠴ 15 done (97/s) | 155ms
#> ⠦ 16 done (99/s) | 162ms
#> ⠧ 17 done (101/s) | 168ms
#> ⠇ 18 done (103/s) | 175ms
#> ⠏ 19 done (103/s) | 186ms
#> ⠋ 20 done (104/s) | 192ms
#> ⠙ 21 done (105/s) | 200ms
#> ⠹ 22 done (107/s) | 207ms
#> ⠸ 23 done (108/s) | 214ms
#> ⠼ 24 done (109/s) | 220ms
#> ⠴ 25 done (111/s) | 227ms
#> ⠦ 26 done (112/s) | 233ms
#> ⠧ 27 done (111/s) | 243ms
#> ⠇ 28 done (112/s) | 250ms
#> ⠏ 29 done (113/s) | 257ms
#> ⠋ 30 done (114/s) | 264ms
#> ⠙ 31 done (115/s) | 271ms
#> ⠹ 32 done (116/s) | 277ms
#> ⠸ 33 done (117/s) | 284ms
#> ⠼ 34 done (116/s) | 294ms
#> ⠴ 35 done (117/s) | 300ms
#> ⠦ 36 done (118/s) | 307ms
#> ⠧ 37 done (118/s) | 313ms
#> ⠇ 38 done (119/s) | 320ms
#> ⠏ 39 done (120/s) | 327ms
#> ⠋ 40 done (120/s) | 333ms
#> ⠙ 41 done (121/s) | 340ms
#> ⠹ 42 done (120/s) | 350ms
#> ⠸ 43 done (121/s) | 356ms
#> ⠼ 44 done (121/s) | 363ms
#> ⠴ 45 done (122/s) | 369ms
#> ⠦ 46 done (123/s) | 376ms
#> ⠧ 47 done (123/s) | 383ms
#> ⠇ 48 done (123/s) | 389ms
#> ⠏ 49 done (123/s) | 400ms
#> ⠋ 50 done (123/s) | 406ms
#> ⠙ 51 done (124/s) | 413ms
#> ⠹ 52 done (124/s) | 419ms
#> ⠸ 53 done (125/s) | 426ms
#> ⠼ 54 done (125/s) | 433ms
#> ⠴ 55 done (125/s) | 439ms
#> ⠦ 56 done (125/s) | 453ms
#> ⠧ 57 done (124/s) | 460ms
#> ⠇ 58 done (124/s) | 467ms
#> ⠏ 59 done (125/s) | 474ms
#> ⠋ 60 done (125/s) | 480ms
#> ⠙ 61 done (125/s) | 487ms
#> ⠹ 62 done (126/s) | 494ms
#> ⠸ 63 done (126/s) | 501ms
#> ⠼ 64 done (125/s) | 511ms
#> ⠴ 65 done (126/s) | 518ms
#> ⠦ 66 done (126/s) | 524ms
#> ⠧ 67 done (126/s) | 531ms
#> # 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.23ms 6.65ms 148. 278KB 23.4
cli_progress_done()