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:
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.
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 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 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 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 following is what I believe to be a typical logger setup:
requireNamespace("logger")
#> Loading required namespace: logger
# 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 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 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 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.")
}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 [2021-11-03 16:36:56] Info message.
cat_info()
#> INFO [2021-11-03 16:36:56] Info message.
logging_info()
#> 2021-11-03 16:36:56 INFO::Info message.
fl_info()
#> INFO [2021-11-03 16:36:56] Info message.
logger_info()
#> INFO [2021-11-03 16:36:56] Info message.
lgr_info()
#> INFO [16:36:56.760] Info message.
loggit_info()
#> {"timestamp": "2021-11-03T16:36:56+0000", "log_lvl": "INFO", "log_msg": "Info message."}
rlog_info()
#> 2021-11-03 16:36:56 [INFO] Info message.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)
)print(info_bench, order = "median")
#> Unit: microseconds
#> expr min lq mean median uq max neval
#> cat 27.3 38.40 54.8350 42.20 53.40 2811.2 500
#> log4r 27.5 51.55 60.5710 59.30 66.95 1063.6 500
#> rlog 63.2 96.60 109.0474 107.00 118.25 1057.1 500
#> logger 224.9 284.25 316.7576 298.50 311.85 3344.8 500
#> futile.logger 329.6 371.10 417.8544 384.55 400.60 6622.7 500
#> logging 334.5 383.55 430.3466 398.00 416.00 7507.2 500
#> lgr 581.8 623.50 723.2016 636.95 657.80 32785.8 500
#> loggit 763.6 798.40 842.3320 818.75 841.80 3912.4 500print(debug_bench, order = "median")
#> Unit: microseconds
#> expr min lq mean median uq max neval
#> cat 1.7 2.70 5.7314 4.20 5.60 788.6 500
#> log4r 8.8 10.80 15.9736 13.35 16.50 1022.9 500
#> rlog 11.6 15.10 21.2040 20.70 23.45 872.8 500
#> lgr 14.2 18.40 38.2624 25.00 29.80 3101.5 500
#> logger 22.8 28.40 43.6884 32.50 43.70 3053.3 500
#> logging 21.8 28.80 41.3526 43.20 48.95 1148.5 500
#> futile.logger 228.1 250.65 267.0700 262.35 276.85 1212.5 500