Logging Performance

Updated as of 2024-10-12

The following vignette presents benchmarks for log4r against all general-purpose logging packages available on CRAN:

Each logging package features slightly different capabilities, but these benchmarks are focused on the two situations common to using all of them:

  1. Logging simple messages to the console; and
  2. 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  [2024-10-12 00:35:22] Info message.
cat_info()
#> INFO  [2024-10-12 00:35:22] Info message.
logging_info()
#> 2024-10-12 00:35:22.582721 INFO::Info message.
fl_info()
#> INFO [2024-10-12 00:35:22] Info message.
logger_info()
#> INFO [2024-10-12 00:35:22] Info message.
lgr_info()
#> INFO  [00:35:22.588] Info message.
loggit_info()
#> {"timestamp": "2024-10-12T00:35:22-0400", "log_lvl": "INFO", "log_msg": "Info message."}
rlog_info()
#> 2024-10-12 00:35:22.590646 [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   24.606   32.9470   36.46860   34.4645   36.5990   790.553
#>            cat   42.360   49.0670   54.74075   52.3280   55.2140  1174.072
#>           rlog   72.807   86.8880   91.64763   89.7235   93.0645   760.426
#>         logger  187.802  208.6260  227.08602  213.5105  221.2045  2559.952
#>        logging  250.289  271.4195  297.23647  277.9565  285.8615  6043.315
#>            lgr  410.149  433.6680  514.84438  442.4900  455.7845 27092.424
#>         loggit  551.164  582.5325  614.46588  592.3410  606.4575  3004.305
#>  futile.logger 1781.251 1837.2360 1975.10361 1859.8330 1887.3850  6475.376
#>  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   2.124   2.8000   4.561908   3.467   3.6870  628.318   500
#>          log4r   2.775   3.2810   5.496310   3.977   4.8240  727.564   500
#>           rlog   6.913   7.9650  10.732968   9.954  10.6800  648.016   500
#>            lgr  13.566  15.3140  19.107736  18.404  19.3415  826.921   500
#>        logging  16.812  19.1210  24.741822  22.938  26.2090  919.996   500
#>         logger  16.641  18.7955  28.088108  23.219  24.2955 2302.388   500
#>  futile.logger 544.782 560.7920 592.952722 567.505 574.5425 4851.369   500