Performance of TLS encryption with a small number of small tasks

[wlandau]

Hi @shikokuchuo,

I hope you enjoyed your holidays!

Since mirai and nanonext are more robust than ever, I find myself thinking about performance, specifically when it comes to TLS encryption.

On my local Ubuntu machine, the following example with 100 tasks and TLS encryption takes almost 9 seconds to complete. I notice similar encryption-specific overhead when testing crew.aws.batch using real-life AWS Batch jobs.

library(nanonext) # 0.11.0.9005
library(mirai) # 0.11.3.9003
daemons(n = 1L, dispatcher = TRUE, url = host_url(ws = TRUE, tls = TRUE))
url <- rownames(status()$daemons)
cv <- nextget("cv")
cv2 <- cv()
cv %~>% cv2
system(launch_remote(url = url), wait = FALSE)
msleep(5000)
n <- 1e2
start <- proc.time()["elapsed"]
tasks <- replicate(n, mirai(TRUE))
while (cv_value(cv) < n) {
  until_(cv2, 500)
}
lapply(tasks, unresolved)
elapsed <- unname(proc.time()["elapsed"] - start)
daemons(n = 0L)
print(elapsed)

When I turn off encryption, the same workload completes in under a tenth of a second.

library(nanonext) # 0.11.0.9005
library(mirai) # 0.11.3.9003
daemons(n = 1L, dispatcher = TRUE)
url <- rownames(status()$daemons)
cv <- nextget("cv")
cv2 <- cv()
cv %~>% cv2
launch_local(url = url)
msleep(2000)
n <- 1e2
start <- proc.time()["elapsed"]
tasks <- replicate(n, mirai(TRUE))
while (cv_value(cv) < n) {
  until_(cv2, 500)
}
lapply(tasks, unresolved)
elapsed <- unname(proc.time()["elapsed"] - start)
daemons(n = 0L)
print(elapsed)

I know there is inevitable overhead from encryption/decryption and maybe extra steps in the handshake, but I would not have expected the slowdown to be quite this much, especially given how fast HTTP and HTTPS both load web pages.

You may already know where the bottleneck comes from, but I set up a quick profiling study anyway using gperftools and a few modifications in wlandau@dda175d:

library(nanonext) # my fork
library(mirai) # 0.11.3.9003
daemons(n = 1L, dispatcher = TRUE, url = host_url(ws = TRUE, tls = TRUE))
url <- rownames(status()$daemons)
cv <- nextget("cv")
cv2 <- cv()
cv %~>% cv2
system(launch_remote(url = url), wait = FALSE)
msleep(5000)
n <- 1e2
samples <- tempfile()
profiler_start(path = samples)
tasks <- replicate(n, mirai(TRUE))
while (cv_value(cv) < n) {
  until_(cv2, 500)
}
daemons(n = 0L)
profiler_stop()
proffer::serve_pprof(pprof = samples)

Unfortunately the flame graph is not useful. Looks like either a standard library function or system call is taking the most time, or the bottleneck comes from a non-interactive external process or thread.

[shikokuchuo]

Turned out to be an a rather obscure reason. Updating the NNG source bundle in 5e984a9 fixes this.

You should find that TLS timings are now only fractionally higher than for non-TLS.