Archives/gristlabs_grist-core
1
0
Fork 0
mirror of https://github.com/gristlabs/grist-core.git synced 2024-10-27 20:44:07 +00:00
Code Issues Projects Releases Wiki Activity

(core) Log the time taken by decodeActionFromRow() operations.

Browse Source 
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
This commit is contained in:
Dmitry S 2021-08-20 01:55:05 -04:00
parent 9f25a96d18
commit 00c1a0c688
2 changed files with 22 additions and 7 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

10
app/server/lib/ActionHistoryImpl.ts
View File

@ -5,6 +5,7 @@ import {LocalActionBundle} from 'app/common/ActionBundle';
import {ActionGroup} from 'app/common/ActionGroup'; import {ActionGroup} from 'app/common/ActionGroup';
import * as marshaller from 'app/common/marshal'; import * as marshaller from 'app/common/marshal';
import {DocState} from 'app/common/UserAPI'; import {DocState} from 'app/common/UserAPI';
import {reportTimeTaken} from 'app/server/lib/reportTimeTaken';
import * as crypto from 'crypto'; import * as crypto from 'crypto';
import keyBy = require('lodash/keyBy'); import keyBy = require('lodash/keyBy');
import mapValues = require('lodash/mapValues'); import mapValues = require('lodash/mapValues');
@ -372,12 +373,13 @@ export class ActionHistoryImpl implements ActionHistory {
public async getRecentActions(maxActions?: number): Promise<LocalActionBundle[]> { public async getRecentActions(maxActions?: number): Promise<LocalActionBundle[]> {
const actions = await this._getRecentActionRows(maxActions); 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[]> { public async getRecentActionGroups(maxActions: number, options: ActionGroupOptions): Promise<ActionGroup[]> {
const actions = await this._getRecentActionRows(maxActions); 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[]> { 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 const actions = await this._db.all(`SELECT actionHash, actionNum, body FROM _gristsys_ActionHistory
where actionNum in (${actionNums.map(x => '?').join(',')})`, where actionNum in (${actionNums.map(x => '?').join(',')})`,
actionNums); actionNums);
return reportTimeTaken("getActions", () => {
const actionsByActionNum = keyBy(actions, 'actionNum'); const actionsByActionNum = keyBy(actions, 'actionNum');
return actionNums return actionNums
.map(n => actionsByActionNum[n]) .map(n => actionsByActionNum[n])
.map((row) => row ? decodeActionFromRow(row) : undefined); .map((row) => row ? decodeActionFromRow(row) : undefined);
});
} }
/** /**
@ -591,7 +595,7 @@ export class ActionHistoryImpl implements ActionHistory {
private async _fetchActions(start: ActionIdentifiers|null, private async _fetchActions(start: ActionIdentifiers|null,
end: ActionIdentifiers|null): Promise<LocalActionBundle[]> { end: ActionIdentifiers|null): Promise<LocalActionBundle[]> {
const rows = await this._fetchParts(start, end, "body, actionNum, actionHash"); const rows = await this._fetchParts(start, end, "body, actionNum, actionHash");
return rows.map(decodeActionFromRow); return reportTimeTaken("_fetchActions", () => rows.map(decodeActionFromRow));
} }
/** /**

11
app/server/lib/reportTimeTaken.ts Normal file
View File

@ -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);
}
}