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-12-17 03:11:16] Info message.
cat_info()
#> INFO  [2024-12-17 03:11:16] Info message.
logging_info()
#> 2024-12-17 03:11:16.243717 INFO::Info message.
fl_info()
#> INFO [2024-12-17 03:11:16] Info message.
logger_info()
#> INFO [2024-12-17 03:11:16] Info message.
lgr_info()
#> INFO  [03:11:16.249] Info message.
loggit_info()
#> {"timestamp": "2024-12-17T03:11:16+0000", "log_lvl": "INFO", "log_msg": "Info message."}
rlog_info()
#> 2024-12-17 03:11:16.252017 [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   25.567   36.2130   44.51911   38.1060   39.6490  2625.311
#>            cat   42.749   49.1965   54.60977   52.7635   54.7420  1146.336
#>           rlog   81.411   96.3850  102.07672  101.2840  103.9035   833.553
#>         logger  187.228  228.2305  247.61484  235.1430  239.7170  2832.257
#>        logging  267.539  301.6025  333.39418  314.8620  322.3855  6695.325
#>            lgr  450.590  488.6500  560.48358  500.0265  511.1770 29007.337
#>         loggit  589.198  639.1510  686.39721  651.5395  668.5955  3578.417
#>  futile.logger 1945.335 2028.4795 2154.88371 2054.3125 2089.4735  7296.255
#>  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.844   2.7350   4.887942   3.9475   4.3435  626.167   500
#>          log4r   2.545   3.6220   6.298338   4.6635   5.6705  809.308   500
#>           rlog   6.362   8.2205  11.704108  10.9350  11.8570  703.921   500
#>            lgr  12.573  15.0030  19.728014  17.7830  20.8440  814.006   500
#>         logger  15.489  18.5595  24.685036  23.0680  27.3010  708.831   500
#>        logging  16.161  20.2930  27.101984  24.5500  30.3365  730.241   500
#>  futile.logger 568.940 588.7620 628.492324 598.1640 611.8450 3629.803   500