Here’s a general purpose timer for wrapping functions without having to edit them to put timers around them.

This is something I often have to do if tracking down performance problems, so I thought I’d start to take a look at what Sheets gets up to.

Let’s say you have a function like this you want to time

function getData (id, sheetName) {

  return SpreadsheetApp.openById(id).getSheetByName(sheetName).getDataRange().getValues();

}
Certainly you could edit it to put start and finish times around it, but if you are timing a few functions, its better to have a standard way of doing it by proxy.
Using some of the techniques in function ‘currying’, I came up with this as a general timer that can be used to wrap any functions in a timer, execute the function and return the timing information and function results.
/**
 * takes a function and its arguments, runs it and times it
 * @param {func} the function
 * @param {...} the rest of the arguments
 * @return {object} the timing information and the function results
 */
function timeFunction () {

    var timedResult = {
      start: new Date().getTime(),
      finish: undefined,
      result: undefined,
      elapsed:undefined
    }
    // turn args into a proper array
    var args = Array.prototype.slice.call(arguments);
    
    // the function name will be the first argument
    var func = args.splice(0,1)[0];
    
    // the rest are the arguments to fn - execute it
    timedResult.result = func.apply(func, args); 
    
    // record finish time
    timedResult.finish = new Date().getTime();
    timedResult.elapsed = timedResult.finish - timedResult.start;
    
    return timedResult;
}
It can be used like this.
function testTime() {

  // compare 2 sheets
  Logger.log('lookup took:' + timeFunction (getData , "19wbpUHwuIKbHaaIiylVSuG7lkK29uoAmYrTvTk_J2ho", "lookup").elapsed);
  Logger.log('lookup stats:' + timeFunction (getData , "19wbpUHwuIKbHaaIiylVSuG7lkK29uoAmYrTvTk_J2ho", "stats").elapsed);

  // the second time 
  Logger.log('lookup took:' + timeFunction (getData , "19wbpUHwuIKbHaaIiylVSuG7lkK29uoAmYrTvTk_J2ho", "lookup").elapsed);
  Logger.log('lookup stats:' + timeFunction (getData , "19wbpUHwuIKbHaaIiylVSuG7lkK29uoAmYrTvTk_J2ho", "stats").elapsed);

  // the results of the timed function and timing information are all returned
  var timer =   timeFunction (getData , "19wbpUHwuIKbHaaIiylVSuG7lkK29uoAmYrTvTk_J2ho", "lookup");
    var data = timer.result;
    var elapsed = timer.elapsed;
    var start = timer.start;
    var finish = timer.finish;
}

Results

[15-07-24 12:23:21:707 BST] lookup took:210
[15-07-24 12:23:21:849 BST] lookup stats:142
[15-07-24 12:23:21:943 BST] lookup took:93
[15-07-24 12:23:22:034 BST] lookup stats:90
Having run this a few times, I now know that there is some caching going on with the Spreadsheet service.
Notice that the second pair of results are much shorter than the first (the values from the sheet are cached), and that the second sheet is shorter to get than the first (the spreadsheet object is somehow caching)
timeFunction is available in the cUseful library.
Many of the snippets in this section of the site are part of the cUseful library. You can find the details here.
For more like this see Google Apps Scripts Snippets
Why not join our forum, follow the blog or follow me on Twitter to ensure you get updates when they are available.