R: how to make system.time print the expression being timed?

Question

I have a big agglomeration of R functions calling each other, they may take a lot of time, so I call them using system.time:

f1 <- function () {
  print(system.time(f1.1()))
  print(system.time(f1.2()))
  print(system.time(f1.3()))
}
...
f <- function () {
  print(system.time(f1()))
  print(system.time(f2()))
  print(system.time(f3()))
}

and then the output from f() looks like

             user            system           elapsed 
129.599 (2.16min)  0.663 (663.00ms) 130.438 (2.17min) 
    wrote 447,337,021 bytes
              user             system            elapsed 
2746.37 (45.77min)  145.299 (2.42min) 2896.68 (48.28min) 
            user           system          elapsed 
 9.544 (9.54sec) 0.755 (755.00ms)  10.3 (10.30sec) 

and it takes some time to figure out the correspondence between functions and timings.

I tried this function:

verbose <- function (expr) {
  ret <- system.time(expr)
  cat("<<<<<<")
  print(expr)
  print(ret)
}
> verbose(Sys.sleep(2))
<<<<<<NULL
           user          system         elapsed 
     0 (0.00ms)      0 (0.00ms) 2.002 (2.00sec) 

Alas, it prints NULL instead of Sys.sleep(2) (i.e., the value instead of the expression).

So, how do I save the expr's printed representation in verbose for future output?

Answer 1

Your function verbose can, by adding substitute, print the value that you pass to the argument expr.

Change the line print(expr) to

print(substitute(expr))

Then

> verbose(Sys.sleep(2))
<<<<<<Sys.sleep(2)
   user  system elapsed 
  0.023   0.007   2.009