A small bit of code to log how long something took

timing.R

# Ever want to log how long someting takes? I know I do. timing()
# isn't about benchmarking, it's about getting feedback from long running
# tasks, especially if they are scheduled in production. Anyway, I love
# this function because it's a simple wrapper that can go around anything.
# I use it inside our tools at Allovue when extracting data to get things
# like this:

#> accounts <- extract_data(config_file$accounts)
# Starting queries/accounts.sql at: Mon Sep 19 15:27:34 2016 
# Completed at: Mon Sep 19 15:28:14 2016 
# Elapsed Time: 40 secs

# This way I know how long a database query takes each time a run it and
# I am able to see how long multiple data pulls took the previous night
# or what pull actually failed (since extract_data is often FUN in lapply.

#' \code{timing} is used to wrap a function and \code{cat} the start time,
#' end time, and elapsed time. This is used primarily to provide feedback
#' during long wrong \code{extract_data} calls.
#' @param f a generic function
#' @param ... the arguments for function f
#' @param msg a character string that states what's being run. Default is ''.
#' @return the results of \code{f(...)} with timing messages in the REPL.


#' @export
timing <- function(f, ..., msg = '') {
  start_time <- format(Sys.time(), '%a %b %d %X %Y')
  start_msg <- paste('Starting', msg,
                     'at:', start_time, '\n')
  cat(start_msg)
  x <- f(...)
  end_time <- format(Sys.time(), '%a %b %d %X %Y')
  end_msg <- paste('Completed', 'at:', end_time, '\n')
  cat(end_msg)
  elapsed <- difftime(as.POSIXlt(end_time, format = '%a %b %d %X %Y'),
                      as.POSIXlt(start_time, format = '%a %b %d %X %Y'))
  cat('Elapsed Time: ', format(unclass(elapsed), digits = getOption('digits')),
      ' ', attr(elapsed, 'units'), '\n\n\n', sep = '')
  x
}