CODEWITHSUNDEEP
rtiming
sds
sds

Reputation: 60004

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

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?

Upvotes: 5

Views: 1850

Answers (2)

BenBarnes
BenBarnes

Reputation: 19454

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

Upvotes: 3

Ricardo Saporta
Ricardo Saporta

Reputation: 55340

While not exactly what you are asking for, I use the following wrapper to System.time which I keep as part of my personal utils file: 

  s.t <- function(expr, msg="", verbose=TRUE, gcFirst=FALSE, title="") { 
  # wrapper for system.time
  # title is an alternate for msg, where user needs simply give a name to the section being timed.
  # msg is for a custome message before the sytem.time output

    ret <- capture.output(system.time(expr=expr, gcFirst=gcFirst))
    ret <- paste(ret, collapse="\n")

    if (nchar(title))
      msg <- paste0("Time to complete ", title, ":")

    if (verbose){
      if (nchar(msg) == 0)
        cat(ret)
      else 
        cat(paste(msg, collapse=""), ret, sep="\n")
    }
  }


I use this in conjunction with an optional verbose flag so that I can easily turn off all the timings if needed.

Upvotes: 0

Related Questions