Example using Stackdriver logging for debugging a custom function for sheets in Google Apps Script. / Writing a Caching custom function

StackTraces-Logging-GAS.md

Logging custom functions using stackdriver in google apps script

Recently, console logging became available for Google Apps Script projects. It used to be impossible to use the Log service that comes with the GAS runtime, but now all you need to do is throw an exception. Exceptions get logged in stackdriver logging and when enabled, unhandled exceptions will not stop your script execution. This adds up to nearly 0 lag if you are using this feature (?) by purposely throwing exceptions, and you can get creative with your error message to avoid having to expand stackdriver's log messages (which are pretty comprehensive stacktraces!)

Setup

So, first you need to set up your project for console logging:

First open View/Console Logs:

First time you enable for each project you will get this notice:

I dont think you can disable this, although i guess it would be good to comment/deactivate/delete your debugging code throwing exceptions before deploying live.

Create a Cacheservice instance:

Create a cache by doing this on the global scope:

kch = CacheService.getDocumentCache(); // set up the cache service as a global object

Then start warming/filling your cache instance by writing results of expensive operations so you dont have to do them again for keys that get repeated oftenly on our input data, use the input value o your functiom as the key, and the return value of your function as the value, like so:

Warm it up

Dont forget only string key/value pairs can live in the cache, so cast accordingly when writing or retrieving values to the cache:

var seconds = 600
du = seconds / 86400;                  // do the math
kch.put(seconds, du, 120);             // put the answer on cache, so it gets warmer (key, value, TTL)
du = kch.get(seconds.toString());      // retrieve cached value, if any (only strings live there)

so here is the whole example:

kch = CacheService.getDocumentCache(); // set up the cache service as a global object
/**
 * Returns the duration formatted value from an integer number of seconds.
 *
 * @param {Seconds} elapsed seconds to convert.
 * @return {String} duration formatted dateString.
 * @customfunction
 */
function SECONDS_TO_DURATION(seconds) {
  var du = kch.get(seconds.toString());      // retrieve cached value, if any (only strings live there)
  if (du) {                                  // let us know if cache was hit
      var hit=true;                          // so we can log this further down
  }
  if (!du) {                                 // bummer! cache miss, 
    du = seconds / 86400;                    // do the math
    kch.put(seconds, du, 120);               // put the answer on cache, so it gets warmer
  }
  if (hit){                                  // This block raises unhandled exceptions 
    throw "hit:"+ du+" seconds:"+ seconds;   // if cache hit, show us the retrieved value from cache
  } else {                                   //
    throw "miss:"+du;                        // if cache miss, show us the noncached key
  }
  return parseInt(du);
}

On the trace log, you can actually see the cache filling up, execution for 1000 cells went from 4 minutes to 2 seconds

Caching function pattern sans debugging code:

/**
 * Returns the duration formatted value from an integer number of seconds.
 *
 * @param {Seconds} elapsed seconds to convert.
 * @return {String} duration formatted dateString.
 * @customfunction
 */
function SECONDS_TO_DURATION(seconds) {
  var du = kch.get(seconds.toString());      // retrieve cached value, if any
  if (!du) {                                 // bummer! cache miss, 
    du = seconds / 86400;                    // do the math
    kch.put(seconds, du, 120);               // put the answer on cache
  }
  return parseInt(du);
}

See your cache coming to life

At first, nearly all attempts are misses, but we're already caching the results, so answers shoud be coming from the cache instead of the potentially expensive math operation.

However a couple of milliseconds into the loop, the cache is getting warmer, and returning results:

Towards the end of the run, nearly all results are cached:

So there.