Simple Benchmarks on logger Performance

Although this has not been an important feature in the early development and overall design of this logger implementation, but with the default ?layout_simple and ?formatter_glue, it seems to perform pretty well when comparing with futile.logger and logging packages:

library(microbenchmark)

## fl
library(futile.logger)
t1 <- tempfile()
flog.appender(appender.file(t1))
#> NULL

## lg
library(logging)
t2 <- tempfile()
addHandler(writeToFile, file = t2)

## lr
library(logger)
#> The following objects are masked from ‘package:futile.logger’: DEBUG, ERROR, FATAL, INFO, TRACE, WARN
t3 <- tempfile()
log_appender(appender_file(t3))

string_fl <- function() flog.info('hi')
string_lg <- function() loginfo('hi')
string_lr <- function() log_info('hi')
dynamic_fl <- function() flog.info('hi %s', 42)
dynamic_lg <- function() loginfo('hi %s', 42)
dynamic_lr <- function() log_info('hi {42}')
vector_fl <- function() flog.info(paste('hi', 1:5))
vector_lg <- function() loginfo(paste('hi', 1:5))
vector_lr <- function() log_info('hi {1:5}')

microbenchmark(
    string_fl(), string_lg(), string_lr(),
    vector_fl(), vector_lg(), vector_lr(),
    dynamic_fl(), dynamic_lg(), dynamic_lr(),
    times = 1e3)
#> Unit: microseconds
#>          expr      min        lq      mean    median        uq        max neval
#>   string_fl() 1533.379 1650.7915 2510.5517 1759.9345 2885.4465  20835.425  1000
#>   string_lg()  172.963  206.7615  315.6177  237.3150  335.3010  12738.735  1000
#>   string_lr()  227.981  263.4715  390.7139  301.9045  409.0400  11926.974  1000
#>   vector_fl() 1552.706 1661.7030 2434.0460 1766.7485 2819.5525  40892.197  1000
#>   vector_lg()  198.338  234.2355  330.3268  266.7695  358.2510   9969.333  1000
#>   vector_lr()  290.169  337.4730  592.0041  382.4335  537.5485 101946.435  1000
#>  dynamic_fl() 1538.985 1663.7890 2564.6668 1782.1160 2932.7555  46039.686  1000
#>  dynamic_lg()  188.213  226.5370  387.2470  255.1745  350.2015  60737.562  1000
#>  dynamic_lr()  271.478  317.3350  486.1123  360.5815  483.5830  12070.936  1000

paste(t1, length(readLines(t1)))
#> [1] "/tmp/Rtmp3Fp6qa/file7a8919485a36 7000"
paste(t2, length(readLines(t2)))
#> [1] "/tmp/Rtmp3Fp6qa/file7a89b17929f 7000"
paste(t3, length(readLines(t3)))
#> [1] "/tmp/Rtmp3Fp6qa/file289f24c88c41 7000"

So based on the above, non-comprehensive benchmark, it seems that when it comes to using the very base functionality of a logging engine, logging comes first, then logger performs with a bit of overhead due to using glue by default, then comes a bit slower futile.logger.

On the other hand, there are some low-hanging fruits to improve performance, eg caching the logger function in the namespace, or using much faster message formatters (eg paste0 or sprintf instead of glue) if needed -- like what futile.logger and logging are using instead of glue, so a quick logger comparison:

log_formatter(formatter_sprintf)
string <- function() log_info('hi')
dynamic <- function() log_info('hi %s', 42)
vector <- function() log_info(paste('hi', 1:5))

microbenchmark(string(), vector(), dynamic(), times = 1e3)
#> Unit: microseconds
#>       expr     min       lq     mean   median       uq      max neval cld
#>   string() 110.192 118.4850 148.5848 137.1825 152.7275 1312.903  1000  a
#>   vector() 129.111 136.8245 168.9274 155.5840 172.6795 3230.528  1000   b
#>  dynamic() 116.347 124.7620 159.1570 143.2140 160.5040 4397.640  1000  ab

Which suggests that logger is a pretty well-performing log framework.

If you need even more performance with slower appenders, then asynchronous logging is your friend: passing the log messages to a reliable message queue, and a background process delivering those to the actual log destination in the background -- without blocking the main R process. This can be easily achieved in logger by wrapping any appender function in the appender_async function, such as:

## demo log appender that's pretty slow
appender_file_slow <- function(file) {
  force(file)
  function(lines) {
    Sys.sleep(1)
    cat(lines, sep = '\n', file = file, append = TRUE)
  }
}

## create an async appender and start using it right away
log_appender(appender_async(appender_file_slow(file = tempfile())))

async <- function() log_info('Was this slow?')
microbenchmark(async(), times = 1e3)
#> Unit: microseconds
#>     expr     min      lq     mean   median     uq      max neval
#>  async() 511.329 528.247 614.8694 558.2535 616.14 5018.731  1000

Please note that although this ~0.6 ms is significantly higher than the ~0.15 ms we achieved above with the sprintf formatter, but this time we are calling an appender that would take 1 full second to deliver the log message (and not just printing to the console), so bringing that down to less than 1 millisecond is not too bad. If you need even higher throughput, then a custom appender_async without checking on the background process and potentially a faster message queue can bring this even below to 200 µs.



Try the logger package in your browser

Any scripts or data that you put into this service are public.

logger documentation built on Oct. 19, 2021, 9:07 a.m.