Logging Performance

The following vignette presents benchmarks for log4r against all general-purpose logging packages available on CRAN:

futile.logger and logging, which are well-established packages; and
logger, lgr, loggit, and rlog, all of which are relative newcomers.

Each logging package features slightly different capabilities, but these benchmarks are focused on the two situations common to using all of them:

Logging simple messages to the console; and
Deciding not to log a message because it is below the threshold.

The first of these is likely the most common kind of logging done by end users, although some may chose to log to files, over HTTP, or to the system log (among others). Yet a benchmark of these other scenarios would largely show the relative expense of these operations, instead of the overhead of the logic performed by the logging packages themselves.

The second measures the performance impact of leaving logging messages in running code, even if they are below the current threshold of visibility. This is another measure of overhead for each logging package.

Using `cat()`

As a reference point, we can measure how long it takes R itself to write a simple message to the console:

cat_debug <- function() {
  cat() # Print nothing.
}

cat_info <- function() cat(
  "INFO  [", format(Sys.time(), "%Y-%m-%d %H:%M:%S", usetz = FALSE),
  "] Info message.", sep = ""
)

The log4r Package

The following is a typical log4r setup:

log4r_logger <- log4r::logger(threshold = "INFO")

log4r_info <- function() {
  log4r::log_info(log4r_logger, "Info message.")
}

log4r_debug <- function() {
  log4r::log_debug(log4r_logger, "Debug message.")
}

The futile.logger Package

The following is a typical futile.logger setup:

requireNamespace("futile.logger")
#> Loading required namespace: futile.logger

futile.logger::flog.logger()

fl_info <- function() {
  futile.logger::flog.info("Info message.")
}

fl_debug <- function() {
  futile.logger::flog.debug("Debug message.")
}

The logging Package

The following is what I believe to be a typical logging setup:

requireNamespace("logging")
#> Loading required namespace: logging

logging::basicConfig()

logging_info <- function() {
  logging::loginfo("Info message.")
}

logging_debug <- function() {
  logging::logdebug("Debug message.")
}

The logger Package

The following is what I believe to be a typical logger setup:

requireNamespace("logger")
#> Loading required namespace: logger
#> Registered S3 method overwritten by 'logger':
#>   method         from 
#>   print.loglevel log4r

# Match the behaviour of other logging packages and write to the console.
logger::log_appender(logger::appender_stdout)

logger_info <- function() {
  logger::log_info("Info message.")
}

logger_debug <- function() {
  logger::log_debug("Debug message.")
}

The lgr Package

The following is what I believe to be a typical lgr setup:

requireNamespace("lgr")
#> Loading required namespace: lgr

lgr_logger <- lgr::get_logger("perf-test")
lgr_logger$set_appenders(list(cons = lgr::AppenderConsole$new()))
lgr_logger$set_propagate(FALSE)

lgr_info <- function() {
  lgr_logger$info("Info message.")
}

lgr_debug <- function() {
  lgr_logger$debug("Debug message.")
}

The loggit Package

The following is what I believe to be a typical loggit setup. Since we only want to log to the console, set the output file to /dev/null. In addition, loggit does not have a notion of thresholds, so there is no “do nothing” operation to test.

requireNamespace("loggit")
#> Loading required namespace: loggit

if (.Platform$OS.type == "unix") {
  loggit::set_logfile("/dev/null")
} else {
  loggit::set_logfile("nul")
}

loggit_info <- function() {
  loggit::loggit("INFO", "Info message.")
}

The rlog Package

The rlog package currently has no configuration options other than the threshold, which is controlled via an environment variable and defaults to hiding debug-level messages:

requireNamespace("rlog")
#> Loading required namespace: rlog

rlog_info <- function() {
  rlog::log_info("Info message.")
}

rlog_debug <- function() {
  rlog::log_debug("Debug message.")
}

Test All Loggers

Debug messages should print nothing.

log4r_debug()
cat_debug()
logging_debug()
fl_debug()
logger_debug()
lgr_debug()
rlog_debug()

Info messages should print to the console. Small differences in output format are to be expected.

log4r_info()
#> INFO  [2024-11-17 06:11:22] Info message.
cat_info()
#> INFO  [2024-11-17 06:11:22] Info message.
logging_info()
#> 2024-11-17 06:11:22.893265 INFO::Info message.
fl_info()
#> INFO [2024-11-17 06:11:22] Info message.
logger_info()
#> INFO [2024-11-17 06:11:22] Info message.
lgr_info()
#> INFO  [06:11:22.898] Info message.
loggit_info()
#> {"timestamp": "2024-11-17T06:11:22+0000", "log_lvl": "INFO", "log_msg": "Info message."}
rlog_info()
#> 2024-11-17 06:11:22.901599 [INFO] Info message.

Benchmarks

The following benchmarks all loggers defined above:

info_bench <- microbenchmark::microbenchmark(
  cat = cat_info(),
  log4r = log4r_info(),
  futile.logger = fl_info(),
  logging = logging_info(),
  logger = logger_info(),
  lgr = lgr_info(),
  loggit = loggit_info(),
  rlog = rlog_info(),
  times = 500,
  control = list(warmups = 50)
)

debug_bench <- microbenchmark::microbenchmark(
  cat = cat_debug(),
  log4r = log4r_debug(),
  futile.logger = fl_debug(),
  logging = logging_debug(),
  logger = logger_debug(),
  lgr = lgr_debug(),
  rlog = rlog_debug(),
  times = 500,
  control = list(warmups = 50)
)

How long does it take to print messages?

print(info_bench, order = "median")
#> Unit: microseconds
#>           expr      min        lq       mean    median        uq       max
#>          log4r   24.817   36.2275   39.40091   38.0460   39.6845   960.545
#>            cat   40.716   48.8010   55.25378   53.0145   55.3335  1479.243
#>           rlog   79.849   97.0060  102.98679  102.2310  104.4050   842.043
#>         logger  198.651  225.9575  237.26995  236.0110  241.9170  1036.246
#>        logging  271.387  305.2610  329.87273  316.8320  324.7960  6373.978
#>            lgr  449.129  494.4085  572.50806  507.3475  518.3185 28933.893
#>         loggit  605.191  649.3085  688.29309  665.3085  681.8840  3250.362
#>  futile.logger 1974.539 2036.5950 2188.27868 2061.7715 2096.2060  7697.781
#>  neval
#>    500
#>    500
#>    500
#>    500
#>    500
#>    500
#>    500
#>    500

How long does it take to decide to do nothing?

print(debug_bench, order = "median")
#> Unit: microseconds
#>           expr     min       lq       mean   median       uq      max neval
#>            cat   1.904   2.7600   4.916776   3.7775   4.2930  673.488   500
#>          log4r   2.505   3.5810   6.484888   4.5940   5.5355  982.025   500
#>           rlog   6.331   8.0200  11.366904  11.0705  11.9175  654.963   500
#>            lgr  12.873  15.5590  19.677126  19.4870  20.7790  705.749   500
#>         logger  15.710  19.2310  24.867198  22.9430  27.4920  675.963   500
#>        logging  16.491  20.6480  27.253722  28.0020  30.2815  718.072   500
#>  futile.logger 575.866 592.7775 629.102018 601.8090 615.5500 3202.623   500