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::info(log4r_logger, "Info message.")
}

log4r_debug <- function() {
  log4r::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-10-14 20:30:45] Info message.
cat_info()
#> INFO  [2025-10-14 20:30:45] Info message.
logging_info()
#> 2025-10-14 20:30:45.546567 INFO::Info message.
fl_info()
#> INFO [2025-10-14 20:30:45] Info message.
logger_info()
#> INFO [2025-10-14 20:30:45] Info message.
lgr_info()
#> INFO  [20:30:45.553] Info message.
loggit_info()
#> {"timestamp": "2025-10-14T20:30:45+0000", "log_lvl": "INFO", "log_msg": "Info message."}
rlog_info()
#> 2025-10-14 20:30:45.559099 [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   10.465   28.0960   40.02287   37.1690   44.9190  1326.785
#>            cat   16.091   34.6150   55.44947   44.5630   57.4485  2609.190
#>           rlog   45.659   90.9915  121.06160  118.1855  138.2850  1286.440
#>         logger  137.600  252.4305  325.00896  320.2465  374.0280  1799.627
#>        logging  239.803  379.5750  512.37067  515.4715  563.4810  9939.548
#>         loggit  531.435  700.2605  953.62209  983.2520 1062.8760  7540.991
#>            lgr  733.207  921.9870 1378.36174 1288.6735 1408.1280 46178.937
#>  futile.logger 2352.237 2723.9905 3770.18921 3891.1120 4194.8325  9885.588
#>  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
#>            cat    1.436    2.8490    5.779598    4.3860    5.2775   655.000
#>          log4r    1.989    3.4535    9.302172    6.5310    8.7140  1357.364
#>           rlog    4.590    7.8100   15.159156   13.4155   15.7355   611.848
#>            lgr   10.043   15.9095   36.693492   25.0340   28.0320  3585.934
#>         logger   12.404   19.7575   39.255724   32.9325   38.6590  2696.205
#>        logging   11.866   20.7310   37.959866   38.5605   43.8365   956.794
#>  futile.logger 1132.093 1284.6865 1568.280422 1388.6065 1727.0695 13986.530
#>  neval
#>    500
#>    500
#>    500
#>    500
#>    500
#>    500
#>    500

Updated as of 2025-10-14

Using cat()