From 00c1a0c688d109d2ff11b8514820132c20ea0de3 Mon Sep 17 00:00:00 2001
From: Dmitry S <dsagal+git@gmail.com>
Date: Fri, 20 Aug 2021 01:55:05 -0400
Subject: [PATCH] (core) Log the time taken by decodeActionFromRow()
 operations.

Summary:
Decoding large actions is a plausible culprit for hogging CPU time for
certain documents. To begin with, log the time taken for this operation,
so that we can tell if it's a problem in practice.

Test Plan: Should not affect any current behaviors

Reviewers: paulfitz

Reviewed By: paulfitz

Differential Revision: https://phab.getgrist.com/D2989
---
 app/server/lib/ActionHistoryImpl.ts | 18 +++++++++++-------
 app/server/lib/reportTimeTaken.ts   | 11 +++++++++++
 2 files changed, 22 insertions(+), 7 deletions(-)
 create mode 100644 app/server/lib/reportTimeTaken.ts

diff --git a/app/server/lib/ActionHistoryImpl.ts b/app/server/lib/ActionHistoryImpl.ts
index 56051992..6f13a17c 100644
--- a/app/server/lib/ActionHistoryImpl.ts
+++ b/app/server/lib/ActionHistoryImpl.ts
@@ -5,6 +5,7 @@ import {LocalActionBundle} from 'app/common/ActionBundle';
 import {ActionGroup} from 'app/common/ActionGroup';
 import * as marshaller from 'app/common/marshal';
 import {DocState} from 'app/common/UserAPI';
+import {reportTimeTaken} from 'app/server/lib/reportTimeTaken';
 import * as crypto from 'crypto';
 import keyBy = require('lodash/keyBy');
 import mapValues = require('lodash/mapValues');
@@ -372,12 +373,13 @@ export class ActionHistoryImpl implements ActionHistory {
 
   public async getRecentActions(maxActions?: number): Promise<LocalActionBundle[]> {
     const actions = await this._getRecentActionRows(maxActions);
-    return actions.map(decodeActionFromRow);
+    return reportTimeTaken("getRecentActions", () => actions.map(decodeActionFromRow));
   }
 
   public async getRecentActionGroups(maxActions: number, options: ActionGroupOptions): Promise<ActionGroup[]> {
     const actions = await this._getRecentActionRows(maxActions);
-    return actions.map(row => asActionGroup(this, decodeActionFromRow(row), options));
+    return reportTimeTaken("getRecentActionGroups",
+      () => actions.map(row => asActionGroup(this, decodeActionFromRow(row), options)));
   }
 
   public async getRecentStates(maxStates?: number): Promise<DocState[]> {
@@ -394,10 +396,12 @@ export class ActionHistoryImpl implements ActionHistory {
     const actions = await this._db.all(`SELECT actionHash, actionNum, body FROM _gristsys_ActionHistory
                                          where actionNum in (${actionNums.map(x => '?').join(',')})`,
                                        actionNums);
-    const actionsByActionNum = keyBy(actions, 'actionNum');
-    return actionNums
-      .map(n => actionsByActionNum[n])
-      .map((row) => row ? decodeActionFromRow(row) : undefined);
+    return reportTimeTaken("getActions", () => {
+      const actionsByActionNum = keyBy(actions, 'actionNum');
+      return actionNums
+        .map(n => actionsByActionNum[n])
+        .map((row) => row ? decodeActionFromRow(row) : undefined);
+    });
   }
 
   /**
@@ -591,7 +595,7 @@ export class ActionHistoryImpl implements ActionHistory {
   private async _fetchActions(start: ActionIdentifiers|null,
                               end: ActionIdentifiers|null): Promise<LocalActionBundle[]> {
     const rows = await this._fetchParts(start, end, "body, actionNum, actionHash");
-    return rows.map(decodeActionFromRow);
+    return reportTimeTaken("_fetchActions", () => rows.map(decodeActionFromRow));
   }
 
   /**
diff --git a/app/server/lib/reportTimeTaken.ts b/app/server/lib/reportTimeTaken.ts
new file mode 100644
index 00000000..09f3af62
--- /dev/null
+++ b/app/server/lib/reportTimeTaken.ts
@@ -0,0 +1,11 @@
+import * as log from 'app/server/lib/log';
+
+export function reportTimeTaken<T>(locationLabel: string, callback: () => T): T {
+  const start = Date.now();
+  try {
+    return callback();
+  } finally {
+    const timeTaken = Date.now() - start;
+    log.debug("Time taken in %s: %s ms", locationLabel, timeTaken);
+  }
+}