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-10-18 17:06:53] Info message.
cat_info()
#> INFO  [2024-10-18 17:06:53] Info message.
logging_info()
#> 2024-10-18 17:06:53.607616 INFO::Info message.
fl_info()
#> INFO [2024-10-18 17:06:53] Info message.
logger_info()
#> INFO [2024-10-18 17:06:53] Info message.
lgr_info()
#> INFO  [17:06:53.614] Info message.
loggit_info()
#> {"timestamp": "2024-10-18T17:06:53+0000", "log_lvl": "INFO", "log_msg": "Info message."}
rlog_info()
#> 2024-10-18 17:06:53.617732 [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
#>          log4r   17.262   29.2740   34.57392   32.0800   37.8905
#>            cat   30.307   38.4970   45.46430   43.5570   46.1010
#>           rlog   74.098   90.7790   99.89871   97.6470  104.1990
#>         logger  190.366  231.7925  255.01178  245.9495  274.5825
#>        logging  313.906  360.2975  409.30649  381.5120  412.0390
#>         loggit  606.622  659.2610  739.35553  682.8545  724.4570
#>            lgr  852.732  901.8680 1043.21120  936.3430  998.3235
#>  futile.logger 2503.744 2611.5095 2856.43062 2697.2695 2837.4910
#>        max neval
#>    898.257   500
#>   1303.834   500
#>    864.423   500
#>   1459.253   500
#>   6828.136   500
#>   3504.751   500
#>  30231.980   500
#>   6640.775   500

How long does it take to decide to do nothing?

print(debug_bench, order = "median")
#> Unit: microseconds
#>           expr      min        lq        mean    median        uq
#>            cat    2.104    3.1660    5.365492    4.4280    4.8090
#>          log4r    2.514    3.8720    7.078490    5.3700    6.5870
#>           rlog    6.663    8.5455   12.438306   11.9825   12.9790
#>            lgr   13.475   16.1400   26.108580   21.1090   23.0880
#>         logger   15.970   19.9225   27.435514   27.4610   29.6905
#>        logging   17.564   22.4925   31.348734   31.0530   33.5830
#>  futile.logger 1042.827 1065.4280 1138.980634 1082.8860 1112.9070
#>       max neval
#>   661.605   500
#>   837.443   500
#>   680.821   500
#>  2165.763   500
#>   732.828   500
#>  1057.945   500
#>  3283.479   500

Updated as of 2024-10-18

Using cat()