Google Apps Scriptの実行時間を改善した話

背景

先日これを作ったんですが、「アレクサ、育児ノートでうんちを記録して」みたいに頼んだときの応答が遅いという問題があり、妻から苦情が寄せられていました。 miyataro.hatenablog.com

処理の流れとしてはこんな感じです。
f:id:miyataro32:20180503224401p:plain

Lambdaの実行時ログを追ってみたところ、実行時間は4.5~5.0秒程度で、そのうちの殆どをGoogle Apps Script APIの実行が占めていました。ただし、私が書いたスクリプトの実行時間そのものは2秒程度で、それをAPIとして実行するときのオーバーヘッドがかなりあるようでした。
集計してないので一個適当に拾ったログから出した値を載せておくと以下のような感じでした。

処理 実行時間
- Lambdaの処理全体 4807 ms
  - Google Apps Script APIの呼び出し 4741 ms
    - Google Apps Scriptの実行時間 2065 ms
    - API実行にかかるオーバーヘッド(?) 2676 ms
  - Lambda上のその他の処理 66 ms

オーバーヘッドだとしたら長すぎだろっていう気がするけど、調べても何も出てこなかった。

とりあえず、こちらで簡単に改善できる部分のなかで改善の余地があるのが「Google Apps Scriptの実行時間」しかないので、ここを改善しました。

方針

一般的な情報の調査

まず、ここにある情報が全部入りな印象です。
Best Practices  |  Apps Script  |  Google Developers

ここに書いてある内容で速度改善に効果がありそうなものは下記。

  • Minimize calls to other services → やってないので関係ない
  • Use batch operations (Spreadsheetの読み書きはまとめてやったほうが早いよっていう内容)
    → もともとこれには結構気を使って作ったので改善の余地が少なそう
  • Use the Cache service → こんなのあったの知らなかった…

読み書きはまとめたほうが早いよっていうのは以下のサイトを読んで気をつけていたのでそれなりに出来ているはず。
Google Apps Scriptのスプレッドシート読み書きを格段に高速化をする方法
[GAS][スプレッドシート]処理速度を向上するには : 逆引きGoogle Apps Script

今までSpreadsheetの読み書きをしていた部分をCache使って高速化するのが効果大きそうなので、その方向で考えることにしました。

ぼくがかんがえたさいきょうの高速化

基本方針は以下の通り

  • Amazon Echoに対する発話から同期的に起こる処理の中ではできるだけSpreadsheetの読み書きをしない
    • キャッシュを利用した書込キューを実装する
      • 書込はすぐには行わずに書込内容をキューに詰めて応答を返す
      • Google Apps Scriptの定時実行機能を使ってバッチ処理でキューの中身を書込む
    • うんちの記録に対して「本日○回目のうんちです」の応答を返すためにSpreadsheetの読込を行っているが、回数はキャッシュの中の値をインクリメントすることでカウントし、読込をなくす

この記事では書込部分を扱います。

実装

キューの実装

キューはキャッシュに対してrecords-queue-1, records-queue-2...というキーで書込内容のJSONを詰めることで実装する。
enqueue用のポインタとdequeue用のポインタを別々に用意してそれらもキャッシュに置いておく。

まずはキューに詰めるところ。

var recordsBufferCache = {}; // 名前空間の定義

recordsBufferCache.QUEUE_CACHE_KEY_PREFIX = 'records-queue-';
recordsBufferCache.QUEUE_ENQUEUE_POINTER_KEY = 'records-queue-enqueue-pointer';

// 念のため、CacheService.getScriptCache()を何回も呼ばなくて良いようにした。
recordsBufferCache.getCache = function () {
  if (!recordsBufferCache.cache) {
    recordsBufferCache.cache = CacheService.getScriptCache();
  }
  return recordsBufferCache.cache;
};

// これがキューに詰めるメソッド。引数に書込む内容を受け取る。
recordsBufferCache.enqueue = function(row) {
  var startTime = Date.now();
  Logger.log('enqueue started with row : ' + JSON.stringify(row));
  
  var cache = recordsBufferCache.getCache();
  
  // 次に詰めるキューのpointerをキャッシュから取得
  var enqueuePointer = cache.get(recordsBufferCache.QUEUE_ENQUEUE_POINTER_KEY);
  if (enqueuePointer === null) {
    Logger.log('enqueuePointer is missing. Newly start from 0');
    enqueuePointer = 0;
  }
  Logger.log('enqueuePointer is ' + enqueuePointer);

  // キャッシュにキューの情報を詰める。第三引数はキャッシュの保持時間で、最大値(21600sec = 6h)を指定。
  cache.put(recordsBufferCache.QUEUE_CACHE_KEY_PREFIX + enqueuePointer, JSON.stringify(row) ,21600);

  // 次に詰めるキューのポインタをキャッシュに入れる
  enqueuePointer++; // implicitly converted to Number
  cache.put(recordsBufferCache.QUEUE_ENQUEUE_POINTER_KEY, enqueuePointer, 21600);
  
  var executionTime = Date.now() - startTime;
  Logger.log('enqueue took ' + executionTime + ' ms');
};

キューの内容をSpreadsheetに書込むところ

recordsBufferCache.QUEUE_DEQUEUE_POINTER_KEY = 'records-queue-dequeue-pointer';

// これが書込むメソッド。返り値は書込んだ行数。
recordsBufferCache.dequeue = function() {
  var startTime = Date.now();
  Logger.log('dequeue started');
  
  var cache = recordsBufferCache.getCache();
  var enqueuePointer = cache.get(recordsBufferCache.QUEUE_ENQUEUE_POINTER_KEY);
  var dequeuePointer = cache.get(recordsBufferCache.QUEUE_DEQUEUE_POINTER_KEY);

  if (enqueuePointer === null) {
    Logger.log('enqueue has never been called. dequeue process will terminate');
    return 0;
  }
  if (dequeuePointer === null) {
    Logger.log('dequeuePointer is missing. Newly start from 0');
    dequeuePointer = 0;
  }
  Logger.log('enqueuePointer is ' + enqueuePointer + ', dequeuePointer is ' + dequeuePointer);
  
  var rowCnt = 0;

  for (var i = Number(dequeuePointer); i < enqueuePointer; i++) {
    Logger.log('processing with pointer ' + i);
    var rowStr = cache.get(recordsBufferCache.QUEUE_CACHE_KEY_PREFIX + i);
    Logger.log('Write a new record : ' + rowStr);
    var row = JSON.parse(rowStr);

    // ループの中で都度書き込みするのはアンチパターンだが、この処理はバッチ実行するのである程度速度がかかることは許容した
    records.getSheet().appendRow(row);
    
    // 消費済のキューは削除
    cache.remove(recordsBufferCache.QUEUE_CACHE_KEY_PREFIX + i);

    // 次に読むキューのポインタをキャッシュに詰める
    cache.put(recordsBufferCache.QUEUE_DEQUEUE_POINTER_KEY, i + 1, 21600);
    rowCnt++;
  }
  
  var executionTime = Date.now() - startTime;
  Logger.log('dequeue took ' + executionTime + ' ms');
  
  return rowCnt;
};

このような内部関数を作り、それを呼び出す関数を以下の通り実装した。

function writeRecordsInQueue () {
  var startTime = Date.now();
  Logger.log('writeRecordsInQueue started');
  
  var newRowCount = recordsBufferCache.dequeue();
  if (newRowCount > 0) {
    // これはレコード追加に伴ってフロントとして使っているシートを更新する処理
    dashboard.updateDashboardOnRecordsChange(true);
  }
  
  var executionTime = Date.now() - startTime;
  Logger.log('writeRecordsInQueue took ' + executionTime + ' ms');
}

この関数を定期実行するよう設定すればOK
f:id:miyataro32:20180506143408p:plain

キャッシュの期限切れを防止

Google Apps Scriptの仕様でキャッシュは最大6時間で期限切れになってしまうので、定期的にキャッシュを詰め直すことでキャッシュの期限切れを防止してみた。
こういうのGoogle的には絶対やってほしくないやつだと思うけど、、、

function maintainCache () {
  var startTime = Date.now();
  Logger.log('maintainCache started');
  
  var cache = recordsBufferCache.getCache();
  
  [
    recordsBufferCache.QUEUE_ENQUEUE_POINTER_KEY, 
    recordsBufferCache.QUEUE_DEQUEUE_POINTER_KEY
  ].forEach(function (key) {
    var value = cache.get(key);
    cache.put(key, value, 21600);
    Logger.log('[key='+ key + ', value=' + value + ']');
  });
  
  var executionTime = Date.now() - startTime;
  Logger.log('maintainCache took ' + executionTime + ' ms');
}

これを4時間おきに実行するようにした。

まとめ

はじめはこんな感じだった実行時間が

処理 実行時間
- Lambdaの処理全体 4807 ms
  - Google Apps Script APIの呼び出し 4741 ms
    - Google Apps Scriptの実行時間 2065 ms
    - API実行にかかるオーバーヘッド(?) 2676 ms
  - Lambda上のその他の処理 66 ms

こんな感じになりました。

処理 実行時間
- Lambdaの処理全体 1993 ms
  - Google Apps Script APIの呼び出し 1961 ms
    - Google Apps Scriptの実行時間 192 ms
    - API実行にかかるオーバーヘッド(?) 1769 ms
  - Lambda上のその他の処理 32 ms

キューの実装だけじゃなくて他のIOも色々とキャッシュ利用するロジックに変えたので、色々合わさった結果ですが、結構改善できました。（まだ遅いけど）
全体としての修正内容はこんな感じ。 github.com

あと気になるのは下記。

  • キャッシュの読み書きでロック機構が必要ではないか（基本的に更新頻度が低いので今のところ問題は起こっていない）
  • API実行のオーバーヘッド大きすぎではないか

また何かあったら書きます。