Echo Timestamp in R-Mode

Question

I would like to better understand the execution time of instructions in an R script when running in batch mode. Is there a good way to do this?

I had one thought about how I would like it to be done. When executed in batch mode, the source of the echo is indicated in the specified log file. Is there a way to echo the timestamp next to the source code in this log file?

> R CMD BATCH script.R script.Rout 

Here is the result that I see today.

 > tail -f script.Rout ... > # features related to the date > trandateN <- as.integer(trandate) > dayOfWeek <- as.integer(wday(trandate)) > holiday <- mapply(isHoliday, trandate) 

I would like to see something like ...

 > tail -f script.Rout ... 2013-06-27 11:18:01 > # features related to the date 2013-06-27 11:18:01 > trandateN <- as.integer(trandate) 2013-06-27 11:18:05 > dayOfWeek <- as.integer(wday(trandate)) 2013-06-27 11:19:02 > holiday <- mapply(isHoliday, trandate) 

Answer 1

You can use addTaskCallback as follows to create a log of each top-level execution.

 .log <- data.frame(time=character(0), expr=character(0)) .logger <- function(expr, value, ok, visible) { # formals described in ?addTaskCallback time <- as.character(Sys.time()) expr <- deparse(expr) .log <<- rbind(.log, data.frame(time, expr)) return(TRUE) # required of task callback functions } .save.log <- function() { if (exists('.logger')) write.csv(.log, 'log.csv') } addTaskCallback(.logger) x <- 1:10 y <- mean(x) .save.log() .log # time expr # 1 2013-06-27 12:01:45.837 addTaskCallback(.logger) # 2 2013-06-27 12:01:45.866 x <- 1:10 # 3 2013-06-27 12:01:45.876 y <- mean(x) # 4 2013-06-27 12:01:45.900 .save.log() 

Of course, instead of committing a cardinal sin with the growth of the data.frame line, as I am here, you can simply leave the connection open and write it directly to the file, closing the connection using on.exit .

And if you want to be careful in this matter, you can quite successfully package the logging settings in a function.

 .log <- function() { .logger <<- local({ log <- data.frame(time=character(0), expr=character(0)) function(expr, value, ok, visible) { time <- as.character(Sys.time()) expr <- deparse(expr) log <<- rbind(log, data.frame(time, expr)) return(TRUE) } }) invisible(addTaskCallback(.logger)) } .save.log <- function() { if (exists('.logger')) write.csv(environment(.logger)$log, 'log.csv') } .log() x <- 1:10 y <- mean(x) .save.log() 

Answer 2

See ?Sys.time . It returns the datetime POSIXct , which you will need to format when outputting to the log file.

 cat(format(Sys.time()), " is the current time\n")