Echo Timestamp in R Batch Mode

Question

I'd like to better understand the execution duration of statements within an R script when run in batch mode. Is there a good way to do this?

I had one thought on how I'd love to see this done. When executing in batch made the source is echoed to the specified log file. Is there a way for it to echo a timestamp next to the source code in this log file?

> R CMD BATCH script.R script.Rout

Here is the output 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'd 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 the cardinal sin of growing a data.frame row-wise, as I have here, you could just leave a connection open and write directly to file, closing the connection with on.exit.

And if you want to be tidy about it, you can pack the logging setup into a function pretty nicely.

.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 a POSIXct datetime, which you'll need to format when outputting to a log file.

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