Poor Man's Apps Script Performance Metrics

By Luis Peralta

Not so long ago, I was writing about measuring Apps Script function performance, in particular those offered as part of the environment by Google. As add-ons get more complex and we rely more on other APIs that we have no control over, measuring how much we are making the user wait becomes important.

Why poor man’s metrics? Because implementing them will cost nothing. But we are going to pay through hacks here and there to get a nice dashboard of metrics for our add-ons.

Let’s create an utility function timeExecution, that will take two parameters: the function to measure the execution time of and an identifier.

function timeExecution(codeBlock, identifier) {
  // Capture start time
  const startTime = Date.now();

  // Execute the code block
  codeBlock();

  // Capture end time and calculate duration
  const endTime = Date.now();
  const duration = endTime - startTime;

  // Log the result with the identifier
  console.log(`perf:${identifier}: ${duration}ms`);
}

We can use it straight away, for example the following code will measure stashes = getStashes(userEmail):

  var stashes = {};
  timeExecution(() => {
    stashes = getStashes(userEmail);
  }, 'getStashes');

The important detail in the timeExecution function is the format that we are using for logging: perf:identifier: time ms.

We are going to need this just now:

  1. Enable Log Analytics for your logs in your GCP project (it is free, poor man knows)
  2. In GCP, go to Logging –> Log Analytics and jump to the query editor and enter the following query (remember to replace project-name)
SELECT 
    timestamp,
    REGEXP_EXTRACT(JSON_VALUE(json_payload.message), r'^perf:([^:]+):') AS function_name,
    CAST(REGEXP_EXTRACT(JSON_VALUE(json_payload.message), r': (\d+)') AS INT64) AS runtime
FROM 
    `project-name.global._Default._Default`
WHERE
    JSON_VALUE(json_payload.message) LIKE 'perf:%';
ORDER BY timestamp;

Voilà, we are going to be tracing the critical sections of our code and collecting the timing data easily: table with perf metrics

What the query is doing is parsing the specific log lines that match our pre-defined format (start with the string perf:) and extracting the relevant fields. Note that we are sorting by timestamp but we could write any SQL query and rely on GROUP BY etc.

Bonus point: let’s visualize it! Using the above query,

  1. Click on the Chart log view option
  2. On measure, select percentile-95 (or any other)
  3. Add breakdown, select function_name

And get this easily consummable graph:

graph with metrics

There is a saying in Spanish that goes by: Una imagen vale más que mil palabras, which translates in this very particular context to an image is worth more than manually parsing thousand logs.