Server: Add logging statement to evaluate the performance of the sharing service

packages/server/src/models/ShareModel.ts

@@ -8,6 +8,7 @@ import { userIdFromUserContentUrl } from '../utils/routeUtils';
 import { getCanShareFolder } from './utils/user';
 import { isUniqueConstraintError } from '../db';
 import Logger from '@joplin/utils/Logger';
+import { PerformanceTimer } from '../utils/time';
 
 const logger = Logger.create('ShareModel');
 
@@ -184,6 +185,7 @@ export default class ShareModel extends BaseModel<Share> {
 	}
 
 	public async updateSharedItems3() {
+		const perfTimer = new PerformanceTimer(logger, 'updateSharedItems3');
 
 		const addUserItem = async (shareUserId: Uuid, itemId: Uuid) => {
 			try {
@@ -214,11 +216,15 @@ export default class ShareModel extends BaseModel<Share> {
 				return;
 			}
 
+			perfTimer.push('handleCreated');
+
 			const shareUserIds = await this.allShareUserIds(share);
 			for (const shareUserId of shareUserIds) {
 				if (shareUserId === change.user_id) continue;
 				await addUserItem(shareUserId, item.id);
 			}
+
+			perfTimer.pop();
 		};
 
 		const handleUpdated = async (change: Change, item: Item, share: Share) => {
@@ -228,30 +234,36 @@ export default class ShareModel extends BaseModel<Share> {
 
 			if (previousShareId === shareId) return;
 
-			const previousShare = previousShareId ? await this.models().share().load(previousShareId) : null;
+			perfTimer.push('handleUpdated');
 
-			if (previousShare) {
+			try {
-				const shareUserIds = await this.allShareUserIds(previousShare);
+				const previousShare = previousShareId ? await this.models().share().load(previousShareId) : null;
-				for (const shareUserId of shareUserIds) {
+
-					if (shareUserId === change.user_id) continue;
+				if (previousShare) {
-					try {
+					const shareUserIds = await this.allShareUserIds(previousShare);
-						await removeUserItem(shareUserId, item.id);
+					for (const shareUserId of shareUserIds) {
-					} catch (error) {
+						if (shareUserId === change.user_id) continue;
-						if (error.httpCode === ErrorNotFound.httpCode) {
+						try {
-							logger.warn('Could not remove a user item because it has already been removed:', error);
+							await removeUserItem(shareUserId, item.id);
-						} else {
+						} catch (error) {
-							throw error;
+							if (error.httpCode === ErrorNotFound.httpCode) {
+								logger.warn('Could not remove a user item because it has already been removed:', error);
+							} else {
+								throw error;
+							}
 						}
 					}
 				}
-			}
 
-			if (share) {
+				if (share) {
-				const shareUserIds = await this.allShareUserIds(share);
+					const shareUserIds = await this.allShareUserIds(share);
-				for (const shareUserId of shareUserIds) {
+					for (const shareUserId of shareUserIds) {
-					if (shareUserId === change.user_id) continue;
+						if (shareUserId === change.user_id) continue;
-					await addUserItem(shareUserId, item.id);
+						await addUserItem(shareUserId, item.id);
+					}
 				}
+			} finally {
+				perfTimer.pop();
 			}
 		};
 
@@ -265,6 +277,8 @@ export default class ShareModel extends BaseModel<Share> {
 		// that have recently changed, and the performed SQL queries are
 		// index-based.
 		const checkForMissingUserItems = async (shares: Share[]) => {
+			perfTimer.push(`checkForMissingUserItems: ${shares.length} shares`);
+
 			for (const share of shares) {
 				const realShareItemCount = await this.itemCountByShareId(share.id);
 				const shareItemCountPerUser = await this.itemCountByShareIdPerUser(share.id);
@@ -279,6 +293,8 @@ export default class ShareModel extends BaseModel<Share> {
 					}
 				}
 			}
+
+			perfTimer.pop();
 		};
 
 		// This loop essentially applies the change made by one user to all the
@@ -296,6 +312,8 @@ export default class ShareModel extends BaseModel<Share> {
 		// This is probably safer in terms of avoiding race conditions and
 		// possibly faster.
 
+		perfTimer.push('Main');
+
 		while (true) {
 			const latestProcessedChange = await this.models().keyValue().value<string>('ShareService::latestProcessedChange');
 
@@ -310,6 +328,8 @@ export default class ShareModel extends BaseModel<Share> {
 				const shares = await this.models().share().loadByIds(shareIds);
 
 				await this.withTransaction(async () => {
+					perfTimer.push(`Processing ${changes.length} changes`);
+
 					for (const change of changes) {
 						const item = items.find(i => i.id === change.item_id);
 
@@ -335,11 +355,15 @@ export default class ShareModel extends BaseModel<Share> {
 					await checkForMissingUserItems(shares);
 
 					await this.models().keyValue().setValue('ShareService::latestProcessedChange', paginatedChanges.cursor);
+
+					perfTimer.pop();
 				}, 'ShareService::updateSharedItems3');
 			}
 
 			if (!paginatedChanges.has_more) break;
 		}
+
+		perfTimer.pop();
 	}
 
 	public async updateResourceShareStatus(doShare: boolean, _shareId: Uuid, changerUserId: Uuid, toUserId: Uuid, resourceIds: string[]) {

packages/server/src/models/UserItemModel.ts

@@ -3,6 +3,10 @@ import BaseModel, { DeleteOptions, LoadOptions, SaveOptions } from './BaseModel'
 import { unique } from '../utils/array';
 import { ErrorNotFound } from '../utils/errors';
 import { Knex } from 'knex';
+import { PerformanceTimer } from '../utils/time';
+import Logger from '@joplin/utils/Logger';
+
+const logger = Logger.create('UserItemModel');
 
 interface DeleteByShare {
 	id: Uuid;
@@ -121,10 +125,16 @@ export default class UserItemModel extends BaseModel<UserItem> {
 	}
 
 	public async addMulti(userId: Uuid, itemsQuery: Knex.QueryBuilder | Item[], options: SaveOptions = {}): Promise<void> {
+		const perfTimer = new PerformanceTimer(logger, 'addMulti');
+
+		perfTimer.push('Main');
+
 		const items: Item[] = Array.isArray(itemsQuery) ? itemsQuery : await itemsQuery.whereNotIn('id', this.db('user_items').select('item_id').where('user_id', '=', userId));
 		if (!items.length) return;
 
 		await this.withTransaction(async () => {
+			perfTimer.push(`Processing ${items.length} items`);
+
 			for (const item of items) {
 				if (!('name' in item) || !('id' in item)) throw new Error('item.id and item.name must be set');
 
@@ -144,7 +154,11 @@ export default class UserItemModel extends BaseModel<UserItem> {
 					});
 				}
 			}
+
+			perfTimer.pop();
 		}, 'UserItemModel::addMulti');
+
+		perfTimer.pop();
 	}
 
 	public async save(_userItem: UserItem, _options: SaveOptions = {}): Promise<UserItem> {

packages/server/src/utils/time.ts

@@ -2,6 +2,7 @@ import dayjs = require('dayjs');
 import dayJsUtc = require('dayjs/plugin/utc');
 import dayJsDuration = require('dayjs/plugin/duration');
 import dayJsTimezone = require('dayjs/plugin/timezone');
+import { LoggerWrapper } from '@joplin/utils/Logger';
 
 function defaultTimezone() {
 	return dayjs.tz.guess();
@@ -65,3 +66,47 @@ export function timerPop() {
 	// eslint-disable-next-line no-console
 	console.info(`Time: ${t.name}: ${Date.now() - t.startTime}`);
 }
+
+interface PerformanceTimerInfo {
+	id: number;
+	name: string;
+	startTime: number;
+}
+
+export class PerformanceTimer {
+
+	private logger_: LoggerWrapper|typeof console = null;
+	private prefix_ = '';
+	private timers_: PerformanceTimerInfo[] = [];
+	private enabled_ = true;
+	private id_ = 1;
+
+	public constructor(logger: LoggerWrapper|typeof console, prefix: string) {
+		this.logger_ = logger;
+		this.prefix_ = prefix;
+	}
+
+	public get enabled() {
+		return this.enabled_;
+	}
+
+	public set enabled(v: boolean) {
+		this.enabled_ = v;
+	}
+
+	public push(name: string) {
+		if (!this.enabled) return;
+		const id = this.id_;
+		this.id_++;
+		this.logger_.info(`${this.prefix_}#${id}: Start: ${name}`);
+		this.timers_.push({ name, startTime: Date.now(), id });
+	}
+
+	public pop() {
+		if (!this.enabled) return;
+		const t = this.timers_.pop();
+		if (!t) throw new Error('Trying to pop a timer but no timer in the list');
+		this.logger_.info(`${this.prefix_}#${t.id}: Done: ${t.name}: ${((Date.now() - t.startTime) / 1000).toFixed(2)}s`);
+	}
+
+}