Although this has not been an important feature in the early development and overall design of this logger
implementation, but with the default ?layout_simple
and ?formatter_glue
, it seems to perform pretty well when comparing with futile.logger
and logging
packages:
library(microbenchmark) ## fl library(futile.logger) t1 <- tempfile() flog.appender(appender.file(t1)) #> NULL ## lg library(logging) t2 <- tempfile() addHandler(writeToFile, file = t2) ## lr library(logger) #> The following objects are masked from ‘package:futile.logger’: DEBUG, ERROR, FATAL, INFO, TRACE, WARN t3 <- tempfile() log_appender(appender_file(t3)) string_fl <- function() flog.info('hi') string_lg <- function() loginfo('hi') string_lr <- function() log_info('hi') dynamic_fl <- function() flog.info('hi %s', 42) dynamic_lg <- function() loginfo('hi %s', 42) dynamic_lr <- function() log_info('hi {42}') vector_fl <- function() flog.info(paste('hi', 1:5)) vector_lg <- function() loginfo(paste('hi', 1:5)) vector_lr <- function() log_info('hi {1:5}') microbenchmark( string_fl(), string_lg(), string_lr(), vector_fl(), vector_lg(), vector_lr(), dynamic_fl(), dynamic_lg(), dynamic_lr(), times = 1e3) #> Unit: microseconds #> expr min lq mean median uq max neval #> string_fl() 1533.379 1650.7915 2510.5517 1759.9345 2885.4465 20835.425 1000 #> string_lg() 172.963 206.7615 315.6177 237.3150 335.3010 12738.735 1000 #> string_lr() 227.981 263.4715 390.7139 301.9045 409.0400 11926.974 1000 #> vector_fl() 1552.706 1661.7030 2434.0460 1766.7485 2819.5525 40892.197 1000 #> vector_lg() 198.338 234.2355 330.3268 266.7695 358.2510 9969.333 1000 #> vector_lr() 290.169 337.4730 592.0041 382.4335 537.5485 101946.435 1000 #> dynamic_fl() 1538.985 1663.7890 2564.6668 1782.1160 2932.7555 46039.686 1000 #> dynamic_lg() 188.213 226.5370 387.2470 255.1745 350.2015 60737.562 1000 #> dynamic_lr() 271.478 317.3350 486.1123 360.5815 483.5830 12070.936 1000 paste(t1, length(readLines(t1))) #> [1] "/tmp/Rtmp3Fp6qa/file7a8919485a36 7000" paste(t2, length(readLines(t2))) #> [1] "/tmp/Rtmp3Fp6qa/file7a89b17929f 7000" paste(t3, length(readLines(t3))) #> [1] "/tmp/Rtmp3Fp6qa/file289f24c88c41 7000"
So based on the above, non-comprehensive benchmark, it seems that when it comes to using the very base functionality of a logging engine, logging
comes first, then logger
performs with a bit of overhead due to using glue
by default, then comes a bit slower futile.logger
.
On the other hand, there are some low-hanging fruits to improve performance, eg caching the logger
function in the namespace, or using much faster message formatters (eg paste0
or sprintf
instead of glue
) if needed -- like what futile.logger
and logging
are using instead of glue
, so a quick logger
comparison:
log_formatter(formatter_sprintf) string <- function() log_info('hi') dynamic <- function() log_info('hi %s', 42) vector <- function() log_info(paste('hi', 1:5)) microbenchmark(string(), vector(), dynamic(), times = 1e3) #> Unit: microseconds #> expr min lq mean median uq max neval cld #> string() 110.192 118.4850 148.5848 137.1825 152.7275 1312.903 1000 a #> vector() 129.111 136.8245 168.9274 155.5840 172.6795 3230.528 1000 b #> dynamic() 116.347 124.7620 159.1570 143.2140 160.5040 4397.640 1000 ab
Which suggests that logger
is a pretty well-performing log framework.
If you need even more performance with slower appenders, then asynchronous logging is your friend: passing the log messages to a reliable message queue, and a background process delivering those to the actual log destination in the background -- without blocking the main R process. This can be easily achieved in logger
by wrapping any appender function in the appender_async
function, such as:
## demo log appender that's pretty slow appender_file_slow <- function(file) { force(file) function(lines) { Sys.sleep(1) cat(lines, sep = '\n', file = file, append = TRUE) } } ## create an async appender and start using it right away log_appender(appender_async(appender_file_slow(file = tempfile()))) async <- function() log_info('Was this slow?') microbenchmark(async(), times = 1e3) #> Unit: microseconds #> expr min lq mean median uq max neval #> async() 511.329 528.247 614.8694 558.2535 616.14 5018.731 1000
Please note that although this ~0.6 ms is significantly higher than the ~0.15 ms we achieved above with the sprintf
formatter, but this time we are calling an appender that would take 1 full second to deliver the log message (and not just printing to the console), so bringing that down to less than 1 millisecond is not too bad. If you need even higher throughput, then a custom appender_async
without checking on the background process and potentially a faster message queue can bring this even below to 200 µs.
Any scripts or data that you put into this service are public.
Add the following code to your website.
For more information on customizing the embed code, read Embedding Snippets.