diff --git a/app/common/normalizedDateTimeString.ts b/app/common/normalizedDateTimeString.ts new file mode 100644 index 00000000..ad07c3bf --- /dev/null +++ b/app/common/normalizedDateTimeString.ts @@ -0,0 +1,27 @@ +import moment from 'moment'; + +/** + * Output an ISO8601 format datetime string, with timezone. + * Any string fed in without timezone is expected to be in UTC. + * + * When connected to postgres, dates will be extracted as Date objects, + * with timezone information. The normalization done here is not + * really needed in this case. + * + * Timestamps in SQLite are stored as UTC, and read as strings + * (without timezone information). The normalization here is + * pretty important in this case. + */ +export function normalizedDateTimeString(dateTime: any): string { + if (!dateTime) { return dateTime; } + if (dateTime instanceof Date) { + return moment(dateTime).toISOString(); + } + if (typeof dateTime === 'string' || typeof dateTime === 'number') { + // When SQLite returns a string, it will be in UTC. + // Need to make sure it actually have timezone info in it + // (will not by default). + return moment.utc(dateTime).toISOString(); + } + throw new Error(`normalizedDateTimeString cannot handle ${dateTime}`); +} diff --git a/app/gen-server/lib/Housekeeper.ts b/app/gen-server/lib/Housekeeper.ts index 116a3c50..c40379fe 100644 --- a/app/gen-server/lib/Housekeeper.ts +++ b/app/gen-server/lib/Housekeeper.ts @@ -1,6 +1,7 @@ import { ApiError } from 'app/common/ApiError'; import { delay } from 'app/common/delay'; import { buildUrlId } from 'app/common/gristUrls'; +import { normalizedDateTimeString } from 'app/common/normalizedDateTimeString'; import { BillingAccount } from 'app/gen-server/entity/BillingAccount'; import { Document } from 'app/gen-server/entity/Document'; import { Organization } from 'app/gen-server/entity/Organization'; @@ -16,7 +17,6 @@ import log from 'app/server/lib/log'; import { IPermitStore } from 'app/server/lib/Permit'; import { optStringParam, stringParam } from 'app/server/lib/requestUtils'; import * as express from 'express'; -import moment from 'moment'; import fetch from 'node-fetch'; import * as Fetch from 'node-fetch'; import { EntityManager } from 'typeorm'; @@ -416,32 +416,6 @@ export class Housekeeper { } } -/** - * Output an ISO8601 format datetime string, with timezone. - * Any string fed in without timezone is expected to be in UTC. - * - * When connected to postgres, dates will be extracted as Date objects, - * with timezone information. The normalization done here is not - * really needed in this case. - * - * Timestamps in SQLite are stored as UTC, and read as strings - * (without timezone information). The normalization here is - * pretty important in this case. - */ -function normalizedDateTimeString(dateTime: any): string { - if (!dateTime) { return dateTime; } - if (dateTime instanceof Date) { - return moment(dateTime).toISOString(); - } - if (typeof dateTime === 'string') { - // When SQLite returns a string, it will be in UTC. - // Need to make sure it actually have timezone info in it - // (will not by default). - return moment.utc(dateTime).toISOString(); - } - throw new Error(`normalizedDateTimeString cannot handle ${dateTime}`); -} - /** * Call callback(item) for each item on the list, sleeping periodically to allow other works to * happen. Any time work takes more than SYNC_WORK_LIMIT_MS, will sleep for SYNC_WORK_BREAK_MS. diff --git a/app/server/lib/ActiveDoc.ts b/app/server/lib/ActiveDoc.ts index addf1278..c3fb5be0 100644 --- a/app/server/lib/ActiveDoc.ts +++ b/app/server/lib/ActiveDoc.ts @@ -69,6 +69,7 @@ import {commonUrls, parseUrlId} from 'app/common/gristUrls'; import {byteString, countIf, retryOnce, safeJsonParse, timeoutReached} from 'app/common/gutil'; import {InactivityTimer} from 'app/common/InactivityTimer'; import {Interval} from 'app/common/Interval'; +import {normalizedDateTimeString} from 'app/common/normalizedDateTimeString'; import { compilePredicateFormula, getPredicateFormulaProperties, @@ -2496,6 +2497,23 @@ export class ActiveDoc extends EventEmitter { } } + private _logSnapshotProgress(docSession: OptDocSession) { + const snapshotProgress = this._docManager.storageManager.getSnapshotProgress(this.docName); + const lastWindowTime = (snapshotProgress.lastWindowStartedAt && + snapshotProgress.lastWindowDoneAt && + snapshotProgress.lastWindowDoneAt > snapshotProgress.lastWindowStartedAt) ? + snapshotProgress.lastWindowDoneAt : Date.now(); + const delay = snapshotProgress.lastWindowStartedAt ? + lastWindowTime - snapshotProgress.lastWindowStartedAt : null; + this._log.debug(docSession, 'snapshot status', { + ...snapshotProgress, + lastChangeAt: normalizedDateTimeString(snapshotProgress.lastChangeAt), + lastWindowStartedAt: normalizedDateTimeString(snapshotProgress.lastWindowStartedAt), + lastWindowDoneAt: normalizedDateTimeString(snapshotProgress.lastWindowDoneAt), + delay, + }); + } + private _logDocMetrics(docSession: OptDocSession, triggeredBy: 'docOpen' | 'interval'| 'docClose') { this.logTelemetryEvent(docSession, 'documentUsage', { limited: { @@ -2513,6 +2531,9 @@ export class ActiveDoc extends EventEmitter { ...this._getCustomWidgetMetrics(), }, }); + // Log progress on making snapshots periodically, to catch anything + // excessively slow. + this._logSnapshotProgress(docSession); } private _getAccessRuleMetrics() { diff --git a/app/server/lib/DocStorageManager.ts b/app/server/lib/DocStorageManager.ts index 24c8628e..dbcb0e59 100644 --- a/app/server/lib/DocStorageManager.ts +++ b/app/server/lib/DocStorageManager.ts @@ -11,7 +11,7 @@ import * as gutil from 'app/common/gutil'; import {Comm} from 'app/server/lib/Comm'; import * as docUtils from 'app/server/lib/docUtils'; import {GristServer} from 'app/server/lib/GristServer'; -import {IDocStorageManager} from 'app/server/lib/IDocStorageManager'; +import {IDocStorageManager, SnapshotProgress} from 'app/server/lib/IDocStorageManager'; import {IShell} from 'app/server/lib/IShell'; import log from 'app/server/lib/log'; import uuidv4 from "uuid/v4"; @@ -257,6 +257,10 @@ export class DocStorageManager implements IDocStorageManager { throw new Error('removeSnapshots not implemented'); } + public getSnapshotProgress(): SnapshotProgress { + throw new Error('getSnapshotProgress not implemented'); + } + public async replace(docName: string, options: any): Promise { throw new Error('replacement not implemented'); } diff --git a/app/server/lib/HostedStorageManager.ts b/app/server/lib/HostedStorageManager.ts index 03f80138..9be39f85 100644 --- a/app/server/lib/HostedStorageManager.ts +++ b/app/server/lib/HostedStorageManager.ts @@ -15,7 +15,7 @@ import {IDocWorkerMap} from 'app/server/lib/DocWorkerMap'; import {ChecksummedExternalStorage, DELETED_TOKEN, ExternalStorage, Unchanged} from 'app/server/lib/ExternalStorage'; import {HostedMetadataManager} from 'app/server/lib/HostedMetadataManager'; import {ICreate} from 'app/server/lib/ICreate'; -import {IDocStorageManager} from 'app/server/lib/IDocStorageManager'; +import {IDocStorageManager, SnapshotProgress} from 'app/server/lib/IDocStorageManager'; import {LogMethods} from "app/server/lib/LogMethods"; import {fromCallback} from 'app/server/lib/serverUtils'; import * as fse from 'fs-extra'; @@ -94,6 +94,9 @@ export class HostedStorageManager implements IDocStorageManager { // Time at which document was last changed. private _timestamps = new Map(); + // Statistics related to snapshot generation. + private _snapshotProgress = new Map(); + // Access external storage. private _ext: ChecksummedExternalStorage; private _extMeta: ChecksummedExternalStorage; @@ -223,6 +226,25 @@ export class HostedStorageManager implements IDocStorageManager { return path.basename(altDocName, '.grist'); } + /** + * Read some statistics related to generating snapshots. + */ + public getSnapshotProgress(docName: string): SnapshotProgress { + let snapshotProgress = this._snapshotProgress.get(docName); + if (!snapshotProgress) { + snapshotProgress = { + pushes: 0, + skippedPushes: 0, + errors: 0, + changes: 0, + windowsStarted: 0, + windowsDone: 0, + }; + this._snapshotProgress.set(docName, snapshotProgress); + } + return snapshotProgress; + } + /** * Prepares a document for use locally. Here we sync the doc from S3 to the local filesystem. * Returns whether the document is new (needs to be created). @@ -476,7 +498,11 @@ export class HostedStorageManager implements IDocStorageManager { * This is called when a document may have been changed, via edits or migrations etc. */ public markAsChanged(docName: string, reason?: string): void { - const timestamp = new Date().toISOString(); + const now = new Date(); + const snapshotProgress = this.getSnapshotProgress(docName); + snapshotProgress.lastChangeAt = now.getTime(); + snapshotProgress.changes++; + const timestamp = now.toISOString(); this._timestamps.set(docName, timestamp); try { if (parseUrlId(docName).snapshotId) { return; } @@ -486,6 +512,10 @@ export class HostedStorageManager implements IDocStorageManager { } if (this._disableS3) { return; } if (this._closed) { throw new Error("HostedStorageManager.markAsChanged called after closing"); } + if (!this._uploads.hasPendingOperation(docName)) { + snapshotProgress.lastWindowStartedAt = now.getTime(); + snapshotProgress.windowsStarted++; + } this._uploads.addOperation(docName); } finally { if (reason === 'edit') { @@ -729,6 +759,7 @@ export class HostedStorageManager implements IDocStorageManager { private async _pushToS3(docId: string): Promise { let tmpPath: string|null = null; + const snapshotProgress = this.getSnapshotProgress(docId); try { if (this._prepareFiles.has(docId)) { throw new Error('too soon to consider pushing'); @@ -748,14 +779,18 @@ export class HostedStorageManager implements IDocStorageManager { await this._inventory.uploadAndAdd(docId, async () => { const prevSnapshotId = this._latestVersions.get(docId) || null; const newSnapshotId = await this._ext.upload(docId, tmpPath as string, metadata); + snapshotProgress.lastWindowDoneAt = Date.now(); + snapshotProgress.windowsDone++; if (newSnapshotId === Unchanged) { // Nothing uploaded because nothing changed + snapshotProgress.skippedPushes++; return { prevSnapshotId }; } if (!newSnapshotId) { // This is unexpected. throw new Error('No snapshotId allocated after upload'); } + snapshotProgress.pushes++; const snapshot = { lastModified: t, snapshotId: newSnapshotId, @@ -767,6 +802,10 @@ export class HostedStorageManager implements IDocStorageManager { if (changeMade) { await this._onInventoryChange(docId); } + } catch (e) { + snapshotProgress.errors++; + // Snapshot window completion time deliberately not set. + throw e; } finally { // Clean up backup. // NOTE: fse.remove succeeds also when the file does not exist. diff --git a/app/server/lib/IDocStorageManager.ts b/app/server/lib/IDocStorageManager.ts index 54180a98..a7eba540 100644 --- a/app/server/lib/IDocStorageManager.ts +++ b/app/server/lib/IDocStorageManager.ts @@ -36,6 +36,8 @@ export interface IDocStorageManager { // Metadata may not be returned in this case. getSnapshots(docName: string, skipMetadataCache?: boolean): Promise; removeSnapshots(docName: string, snapshotIds: string[]): Promise; + // Get information about how snapshot generation is going. + getSnapshotProgress(docName: string): SnapshotProgress; replace(docName: string, options: DocReplacementOptions): Promise; } @@ -66,5 +68,45 @@ export class TrivialDocStorageManager implements IDocStorageManager { public async flushDoc() {} public async getSnapshots(): Promise { throw new Error('no'); } public async removeSnapshots(): Promise { throw new Error('no'); } + public getSnapshotProgress(): SnapshotProgress { throw new Error('no'); } public async replace(): Promise { throw new Error('no'); } } + + +/** + * Some summary information about how snapshot generation is going. + * Any times are in ms. + * All information is within the lifetime of a doc worker, not global. + */ +export interface SnapshotProgress { + // The last time the document was marked as having changed. + lastChangeAt?: number; + + // The last time a save window started for the document (checking to see + // if it needs to be pushed, and pushing it if so, possibly waiting + // quite some time to bundle any other changes). + lastWindowStartedAt?: number; + + // The last time the document was either pushed or determined to not + // actually need to be pushed, after having been marked as changed. + lastWindowDoneAt?: number; + + // Number of times the document was pushed. + pushes: number; + + // Number of times the document was not pushed because no change found. + skippedPushes: number; + + // Number of times there was an error trying to push. + errors: number; + + // Number of times the document was marked as changed. + // Will generally be a lot greater than saves. + changes: number; + + // Number of times a save window was started. + windowsStarted: number; + + // Number of times a save window was completed. + windowsDone: number; +}