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 [2022-11-25 15:11:30] Info message.
cat_info()
#> INFO [2022-11-25 15:11:30] Info message.
logging_info()
#> 2022-11-25 15:11:30 INFO::Info message.
fl_info()
#> INFO [2022-11-25 15:11:30] Info message.
logger_info()
#> INFO [2022-11-25 15:11:30] Info message.
lgr_info()
#> INFO [15:11:30.223] Info message.
loggit_info()
#> {"timestamp": "2022-11-25T15:11:30-0500", "log_lvl": "INFO", "log_msg": "Info message."}
rlog_info()
#> 2022-11-25 15:11:30 [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
#> cat 19.727 24.8665 29.67838 27.4510 30.4120 1059.446
#> log4r 14.296 26.0990 38.78562 32.0350 38.8730 2111.388
#> rlog 44.754 59.5615 67.99791 66.2240 73.0670 744.355
#> logger 152.856 175.9850 196.45468 186.4345 200.5960 2265.367
#> logging 195.847 222.2560 252.33351 233.1320 248.1000 5634.985
#> lgr 371.837 402.0790 498.85653 415.8595 437.0245 25077.198
#> loggit 514.625 551.1530 632.20753 567.2740 587.6315 3101.445
#> futile.logger 1509.811 1593.7180 1680.18994 1626.2340 1662.5675 5869.816
#> neval
#> 500
#> 500
#> 500
#> 500
#> 500
#> 500
#> 500
#> 500print(debug_bench, order = "median")
#> Unit: microseconds
#> expr min lq mean median uq max neval
#> cat 1.834 2.5345 4.58175 3.2560 3.5260 757.471 500
#> log4r 2.444 3.2160 5.39048 3.9825 4.7490 684.975 500
#> rlog 6.523 8.0100 10.84480 10.1340 10.9705 607.769 500
#> lgr 11.913 13.9415 21.90749 16.8265 17.6530 2301.315 500
#> logger 14.868 17.8930 26.87330 22.0060 23.4440 2274.245 500
#> logging 14.498 17.4125 22.32278 22.4620 24.1250 634.230 500
#> futile.logger 474.359 494.3515 524.52623 501.6405 512.5060 4638.196 500