Performance of loggers in R

Sep 29, 2022 cha

The performance penalty of the R futile.logger

We will discuss potential performance issue with logger in R, in particular the futile logger. If you're familiar with logger or futile.log you can skip to the "The penalty of the R futile.logger" section below.

It's very common for a developer to print messages while its application is running. This allow him/her to monitor the execution of the application and be aware of any wrongdoing during the execution. A primitive/simple way of doing it is to use the print-like instruction of you favorite language. Like the print in R:

print("Starting computation")
result <- computation(x, y)
if (result < 0) {
  print("Error: unexpected negative result")
  print(paste0("Debug info: the result was", result))
} else {
  print("Debug info: the result was in the accepted range")
}
print("Computation ended")

and this will produce a simple output like:

[1] "Computation ended"
[1] "Debug info: the result was in the accepted range"
[1] "Computation ended"

Using a logger offers the advantage over the print as it attaches a so called level to the messages. The levels allow to group messages according their "importance" and often print automatically valuable information with the message, like a timestamp or the module/class that printed the message. Note that the format of the message can be configured, but this is beyond the scope of this document.

In R, such a logger is available through the library futile.logger and is loosely based on log4j. Below a simple example using the futile.logger:

library(futile.logger)
flog.info("Starting computation")
result <- computation(x, y)
if (result < 0) {
  flog.error("Unexpected negative result")
  flog.debug("The result was %s", result)
} else {
  flog.debug("The result was in the accepted range")
}
flog.info("Computation ended")

and according the level threshold selected the output may vary. E.g the output with the info threshold:

INFO [2021-03-20 12:18:34] Starting computation
INFO [2021-03-20 14:10:44] Computation ended

and the output with the debug threshold of the same run:

INFO  [2021-03-20 12:18:34] Starting computation
DEBUG [2021-03-20 14:10:42] The result was in the accepted range
INFO  [2021-03-20 14:10:44] Computation ended

On can see that in the case of the info threshold only info level are displayed. And with the debug threshold info and debug levels are displayed. The following table illustrates which threshold (T) print which levels (L):

+────────+────────+────────+───────+───────+────────+────────+──────+
| T \ L  | Fatal  | Error  | Warn  | Info  | Debug  | Trace  | All  |
+────────+────────+────────+───────+───────+────────+────────+──────+
| Off    |        |        |       |       |        |        |      |
| Fatal  | Yes    |        |       |       |        |        |      |
| Error  | Yes    | Yes    |       |       |        |        |      |
| Warn   | Yes    | Yes    | Yes   |       |        |        |      |
| Info   | Yes    | Yes    | Yes   | Yes   |        |        |      |
| Debug  | Yes    | Yes    | Yes   | Yes   | Yes    |        |      |
| Trace  | Yes    | Yes    | Yes   | Yes   | Yes    | Yes    |      |
| All    | Yes    | Yes    | Yes   | Yes   | Yes    | Yes    | Yes  |
+────────+────────+────────+───────+───────+────────+────────+──────+

The penalty of the R futile.logger

First of all, the reader should note that this experiment/demo has been executed on a x86-64 pc-linux-gnu and is based on:

  • R version 4.1.2 (2021-11-01) aka Bird Hippie
  • Futile logger 1.4.3

So results may vary depending on the platform and software version.

One issue with the futile.logger in R is that the log calls using levels under the threshold are not eluded by the interpreter. As opposition with what may be done with a complied language. So each call are evaluated, and those calls are not free in evaluation time.

Let's illustrate this by computing the Fibonacci n-th number. The code is pretty straightforward:

rec_fibo_log <- function(n) {
  if (n <= 1) {
    n
  } else {
   rec_fibo_less_log(n-1) + rec_fibo_less_log(n-2)
  }
}

Please note the above code doesn't intend to use any mathematical trick to improve the computation time.

Let's arrange it in a more user friendly and logged manner:

library(futile.logger)

fibo <- function(n) {
  flog.info("Computing Fibonacci sequence of %s", n)
  if (n < 0) {
    flog.error("Negative number provided as input:", n)
    NULL
  } else {
    f <- rec_fibo(n)
    flog.info("Fibbonacci number %s is %s", n, f)
    f
  } 
}

rec_fibo <- function(n) {
  flog.debug("Computing %s", n)
  if (n <= 1) {
    flog.debug("Base case reached")
    n
  } else {
   flog.debug("Continuing recursion for %s and %s", (n-1), (n-2))
   rec_fibo(n-1) + rec_fibo(n-2)
  }
}

Now this where it starts to get a bit "dirty". Keeping the default level, which is info, and computing recursivly the last number of the sequence seems to trigger a call to all logger functions. Despite the messages not being displayed as we should only call the following levels: fatal, error, warn and info. But not the debug level. This can be seen by profiling the code:

Rprof()
fibo(20)
Rprof(NULL)
prof_log <- summaryRprof()

which produces the following output:

INFO [2021-03-20 14:35:20] Computing Fibonacci sequence of 20
INFO [2021-03-20 14:35:50] Fibonacci number 20 is 6765

This is exatly what we want to see: clean and time stamped messages. However the profiler produces:

$by.total
                       total.time total.pct self.time self.pct
"fibo"                       9.18    100.00      0.00     0.00
"rec_fibo"                   9.16     99.78      0.06     0.65
"flog.debug"                 9.10     99.13      0.06     0.65
".log_level"                 9.06     98.69      0.06     0.65
"flog.logger"                9.00     98.04      0.06     0.65
"UseFunction"                8.94     97.39      0.20     2.18
"flog.namespace"             5.80     63.18      0.12     1.31
"capture.output"             5.46     59.48      0.22     2.40
"withVisible"                3.70     40.31      0.08     0.87
    ... (removing non relevant list of calls for lisiblity)
"flog.appender"              0.02      0.22      0.00     0.00
"flog.info"                  0.02      0.22      0.00     0.00
"genCode"                    0.02      0.22      0.00     0.00
"getInlineHandler"           0.02      0.22      0.00     0.00
"tryInline"                  0.02      0.22      0.00     0.00

and:

$sampling.time
[1] 9.18

where we see the top functions regarding the total time are function dedicated to the logger. And by removing the call to the logger at debug levels and keeping only the levels above or equal to the threshold:

library(futile.logger)

fibo <- function(n) {
  flog.info("Computing Fibonacci sequence of %s", n)
  if (n < 0) {
    flog.error("Negative number provided as input:", n)
    NULL
  } else {
    f <- rec_fibo(n)
    flog.info("Fibbonacci number %s is %s", n, f)
    f
  } 
}

rec_fibo <- function(n) {
  if (n <= 1) {
    n
  } else {
   rec_fibo(n-1) + rec_fibo(n-2)
  }
}

produces the same output (see above) and the profiler:

$by.total
           total.time total.pct self.time self.pct
"rec_fibo"       0.02       100      0.02      100
"fibo"           0.02       100      0.00        0

$sampling.time
[1] 0.02

which is an almost immediate computation of the result. So we notice that we roughly have a code which is ≈500 times slower when doing calls to the silenced debug logger in this specific case.

Conclusion

Using a logger is still a very good practice and should be used. We encourage it. This helps structuring the prints and application messages.

However they should be used to produce essential messages in the case of futile.logger. Like general steps of the execution and obviously errors. But not detailed prints dedicated for debugging each deep steps of a computation. Those should be used during the development phase and removed from the code during production.