mirror of
https://github.com/laurent22/joplin.git
synced 2024-12-24 10:27:10 +02:00
Server: Add logging statement to evaluate the performance of the sharing service
This commit is contained in:
parent
9edcd4eb8f
commit
1d6c1e4664
@ -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) {
|
||||
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;
|
||||
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();
|
||||
}
|
||||
};
|
||||
|
||||
@ -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[]) {
|
||||
|
@ -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> {
|
||||
|
@ -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`);
|
||||
}
|
||||
|
||||
}
|
||||
|
Loading…
Reference in New Issue
Block a user