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  [2025-01-16 02:51:54] Info message.
cat_info()
#> INFO  [2025-01-16 02:51:54] Info message.
logging_info()
#> 2025-01-16 02:51:54.393114 INFO::Info message.
fl_info()
#> INFO [2025-01-16 02:51:54] Info message.
logger_info()
#> INFO [2025-01-16 02:51:54] Info message.
lgr_info()
#> INFO  [02:51:54.398] Info message.
loggit_info()
#> {"timestamp": "2025-01-16T02:51:54+0000", "log_lvl": "INFO", "log_msg": "Info message."}
rlog_info()
#> 2025-01-16 02:51:54.401122 [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 neval
#>          log4r   25.948   36.964   40.04963   38.4215   40.2800   826.599   500
#>            cat   41.477   49.412   55.40691   53.7450   55.5480  1177.352   500
#>           rlog   80.901   97.412  103.04802  101.6390  103.9635  1124.755   500
#>         logger  196.817  231.461  238.72858  238.0580  242.3315  1020.500   500
#>        logging  274.571  309.511  329.17018  317.4665  324.3540  6424.032   500
#>            lgr  457.401  497.211  584.90060  507.9710  516.5020 30627.319   500
#>         loggit  606.850  650.005  708.50893  664.1570  678.2435  5957.302   500
#>  futile.logger 1903.344 1985.191 2102.69765 2010.5135 2039.0220  4992.536   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.933   2.7950   5.395746   3.9970   4.3085  857.467   500
#>          log4r   2.495   3.7015   6.310718   4.7940   5.7810  763.522   500
#>           rlog   6.342   7.8495  11.669416  11.1255  11.9375  707.497   500
#>            lgr  12.764  15.2835  19.970730  19.0950  20.8440  704.251   500
#>         logger  15.479  19.5565  25.854668  25.8430  27.6665  725.030   500
#>        logging  16.351  20.4230  27.630800  28.0570  30.5820  762.960   500
#>  futile.logger 559.472 576.3780 628.988730 584.6440 600.1280 3308.119   500