Skip to content

Commit

Permalink
Server: Add logging statement to evaluate the performance of the shar…
Browse files Browse the repository at this point in the history 
…ing service
  • Loading branch information
@laurent22
laurent22 committed Oct 19, 2024
1 parent 9edcd4e commit 1d6c1e4
Show file tree
Hide file tree
Showing 3 changed files with 102 additions and 19 deletions.
62 changes: 43 additions & 19 deletions packages/server/src/models/ShareModel.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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');

Expand Down Expand Up @@ -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 {
Expand Down Expand Up @@ -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) => {
Expand All @@ -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;

if (previousShare) {
const shareUserIds = await this.allShareUserIds(previousShare);
for (const shareUserId of shareUserIds) {
if (shareUserId === change.user_id) continue;
try {
await removeUserItem(shareUserId, item.id);
} catch (error) {
if (error.httpCode === ErrorNotFound.httpCode) {
logger.warn('Could not remove a user item because it has already been removed:', error);
} else {
throw error;
perfTimer.push('handleUpdated');

try {
const previousShare = previousShareId ? await this.models().share().load(previousShareId) : null;

if (previousShare) {
const shareUserIds = await this.allShareUserIds(previousShare);
for (const shareUserId of shareUserIds) {
if (shareUserId === change.user_id) continue;
try {
await removeUserItem(shareUserId, item.id);
} catch (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) {
const shareUserIds = await this.allShareUserIds(share);
for (const shareUserId of shareUserIds) {
if (shareUserId === change.user_id) continue;
await addUserItem(shareUserId, item.id);
if (share) {
const shareUserIds = await this.allShareUserIds(share);
for (const shareUserId of shareUserIds) {
if (shareUserId === change.user_id) continue;
await addUserItem(shareUserId, item.id);
}
}
} finally {
perfTimer.pop();
}
};

Expand All @@ -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);
Expand All @@ -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
Expand All @@ -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');

Expand All @@ -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);

Expand All @@ -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[]) {
Expand Down
14 changes: 14 additions & 0 deletions packages/server/src/models/UserItemModel.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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');

Expand All @@ -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> {
Expand Down
45 changes: 45 additions & 0 deletions packages/server/src/utils/time.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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();
Expand Down Expand Up @@ -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`);
}

}

0 comments on commit 1d6c1e4

Please sign in to comment.