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-03-17 06:20:56] Info message.
cat_info()
#> INFO  [2025-03-17 06:20:56] Info message.
logging_info()
#> 2025-03-17 06:20:56.605788 INFO::Info message.
fl_info()
#> INFO [2025-03-17 06:20:56] Info message.
logger_info()
#> INFO [2025-03-17 06:20:56] Info message.
lgr_info()
#> INFO  [06:20:56.611] Info message.
loggit_info()
#> {"timestamp": "2025-03-17T06:20:56+0000", "log_lvl": "INFO", "log_msg": "Info message."}
rlog_info()
#> 2025-03-17 06:20:56.614103 [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   21.430   34.1590   37.65161   35.9620   37.8560   900.181
#>            cat   36.077   44.4530   50.83554   48.4755   51.0305  1274.720
#>           rlog   77.535   95.0120  101.92322   99.2355  102.7270  1112.487
#>         logger  189.684  228.6370  256.23728  235.1490  249.1800  3259.496
#>        logging  266.688  308.5710  348.59429  318.5045  332.8665  8377.992
#>            lgr  441.194  498.2305  578.18271  512.0410  527.7055 28736.020
#>         loggit  611.582  653.3500  697.79336  670.8325  685.7205  3526.394
#>  futile.logger 1969.998 2035.2195 2166.51810 2057.8670 2090.3180  8293.223
#>  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.914   2.6250   5.229752   3.7320   4.3030  833.516   500
#>          log4r   2.465   3.2660   6.033910   4.6190   5.5750  787.120   500
#>           rlog   6.592   7.8600  11.778634  10.0535  12.2580  739.671   500
#>            lgr  13.024  15.2285  20.149324  19.5815  20.9690  726.015   500
#>         logger  15.649  18.6100  25.121938  25.4980  27.3665  715.827   500
#>        logging  16.341  20.4830  27.867846  28.5930  30.6475  815.242   500
#>  futile.logger 569.212 596.2535 636.233820 608.3765 617.7180 3702.032   500