diff --git a/apps/server/src/core/logger/types/logging.types.ts b/apps/server/src/core/logger/types/logging.types.ts index c5fcdc1f8c9..3bd1839fd8b 100644 --- a/apps/server/src/core/logger/types/logging.types.ts +++ b/apps/server/src/core/logger/types/logging.types.ts @@ -1,3 +1,6 @@ +/** + * Information inside this file should be placed in shared, type are copied to it. + */ export type LogMessage = { message: string; data?: LogMessageData; diff --git a/apps/server/src/modules/tldraw/config.ts b/apps/server/src/modules/tldraw/config.ts index b0a017dd59c..534ecbc06aa 100644 --- a/apps/server/src/modules/tldraw/config.ts +++ b/apps/server/src/modules/tldraw/config.ts @@ -17,6 +17,7 @@ export interface TldrawConfig { API_HOST: number; TLDRAW_MAX_DOCUMENT_SIZE: number; TLDRAW_FINALIZE_DELAY: number; + PERFORMANCE_MEASURE_ENABLED: boolean; } export const TLDRAW_DB_URL: string = Configuration.get('TLDRAW_DB_URL') as string; @@ -24,7 +25,7 @@ export const TLDRAW_SOCKET_PORT = Configuration.get('TLDRAW__SOCKET_PORT') as nu const tldrawConfig = { TLDRAW_DB_URL, - NEST_LOG_LEVEL: Configuration.get('NEST_LOG_LEVEL') as string, + NEST_LOG_LEVEL: Configuration.get('TLDRAW__LOG_LEVEL') as string, INCOMING_REQUEST_TIMEOUT: Configuration.get('INCOMING_REQUEST_TIMEOUT_API') as number, TLDRAW_DB_COMPRESS_THRESHOLD: Configuration.get('TLDRAW__DB_COMPRESS_THRESHOLD') as number, FEATURE_TLDRAW_ENABLED: Configuration.get('FEATURE_TLDRAW_ENABLED') as boolean, @@ -39,6 +40,7 @@ const tldrawConfig = { API_HOST: Configuration.get('API_HOST') as string, TLDRAW_MAX_DOCUMENT_SIZE: Configuration.get('TLDRAW__MAX_DOCUMENT_SIZE') as number, TLDRAW_FINALIZE_DELAY: Configuration.get('TLDRAW__FINALIZE_DELAY') as number, + PERFORMANCE_MEASURE_ENABLED: Configuration.get('TLDRAW__PERFORMANCE_MEASURE_ENABLED') as boolean, }; export const config = () => tldrawConfig; diff --git a/apps/server/src/modules/tldraw/repo/y-mongodb.spec.ts b/apps/server/src/modules/tldraw/repo/y-mongodb.spec.ts index a3a2ae88677..dbdd475a32f 100644 --- a/apps/server/src/modules/tldraw/repo/y-mongodb.spec.ts +++ b/apps/server/src/modules/tldraw/repo/y-mongodb.spec.ts @@ -1,17 +1,17 @@ +import { createMock } from '@golevelup/ts-jest'; +import { MongoMemoryDatabaseModule } from '@infra/database'; import { EntityManager } from '@mikro-orm/mongodb'; +import { ConfigModule } from '@nestjs/config'; import { Test, TestingModule } from '@nestjs/testing'; import { cleanupCollections } from '@shared/testing'; -import { MongoMemoryDatabaseModule } from '@infra/database'; -import { ConfigModule } from '@nestjs/config'; -import { createMock } from '@golevelup/ts-jest'; -import * as Yjs from 'yjs'; import { createConfigModuleOptions } from '@src/config'; import { DomainErrorHandler } from '@src/core'; -import { tldrawEntityFactory, tldrawTestConfig } from '../testing'; +import * as Yjs from 'yjs'; import { TldrawDrawing } from '../entities'; +import { tldrawEntityFactory, tldrawTestConfig } from '../testing'; +import { Version } from './key.factory'; import { TldrawRepo } from './tldraw.repo'; import { YMongodb } from './y-mongodb'; -import { Version } from './key.factory'; jest.mock('yjs', () => { const moduleMock: unknown = { diff --git a/apps/server/src/modules/tldraw/repo/y-mongodb.ts b/apps/server/src/modules/tldraw/repo/y-mongodb.ts index 1ff357bba1c..edc7fae12fc 100644 --- a/apps/server/src/modules/tldraw/repo/y-mongodb.ts +++ b/apps/server/src/modules/tldraw/repo/y-mongodb.ts @@ -1,12 +1,12 @@ import { BulkWriteResult } from '@mikro-orm/mongodb/node_modules/mongodb'; import { Injectable } from '@nestjs/common'; import { ConfigService } from '@nestjs/config'; +import { DomainErrorHandler } from '@src/core'; import { Buffer } from 'buffer'; import * as binary from 'lib0/binary'; import * as encoding from 'lib0/encoding'; import * as promise from 'lib0/promise'; import { applyUpdate, Doc, encodeStateAsUpdate, encodeStateVector, mergeUpdates } from 'yjs'; -import { DomainErrorHandler } from '@src/core'; import { TldrawConfig } from '../config'; import { WsSharedDocDo } from '../domain'; import { TldrawDrawing } from '../entities'; @@ -94,7 +94,8 @@ export class YMongodb { // return value is not void, need to be changed public compressDocumentTransactional(docName: string): Promise { - // return value can be null, need to be defined + performance.mark('compressDocumentTransactional'); + return this._transact(docName, async () => { const updates = await this.getMongoUpdates(docName); const mergedUpdates = mergeUpdates(updates); @@ -105,10 +106,16 @@ export class YMongodb { const stateAsUpdate = encodeStateAsUpdate(ydoc); const sv = encodeStateVector(ydoc); const clock = await this.storeUpdate(docName, stateAsUpdate); + await this.writeStateVector(docName, sv, clock); await this.clearUpdatesRange(docName, 0, clock); ydoc.destroy(); + + performance.measure('tldraw:YMongodb:compressDocumentTransactional', { + start: 'compressDocumentTransactional', + detail: { doc_name: docName, clock }, + }); }); } @@ -143,20 +150,24 @@ export class YMongodb { return this.repo.readAsCursor(query, opts); } - private mergeDocsTogether(doc: TldrawDrawing, docs: TldrawDrawing[], docIndex: number): Buffer[] { - const parts = [Buffer.from(doc.value.buffer)]; - let currentPartId: number | undefined = doc.part; - for (let i = docIndex + 1; i < docs.length; i += 1) { - const part = docs[i]; - - if (!this.isSameClock(part, doc)) { + private mergeDocsTogether( + tldrawDrawingEntity: TldrawDrawing, + tldrawDrawingEntities: TldrawDrawing[], + docIndex: number + ): Buffer[] { + const parts = [Buffer.from(tldrawDrawingEntity.value.buffer)]; + let currentPartId: number | undefined = tldrawDrawingEntity.part; + for (let i = docIndex + 1; i < tldrawDrawingEntities.length; i += 1) { + const entity = tldrawDrawingEntities[i]; + + if (!this.isSameClock(entity, tldrawDrawingEntity)) { break; } - this.checkIfPartIsNextPartAfterCurrent(part, currentPartId); + this.checkIfPartIsNextPartAfterCurrent(entity, currentPartId); - parts.push(Buffer.from(part.value.buffer)); - currentPartId = part.part; + parts.push(Buffer.from(entity.value.buffer)); + currentPartId = entity.part; } return parts; @@ -165,20 +176,20 @@ export class YMongodb { /** * Convert the mongo document array to an array of values (as buffers) */ - private convertMongoUpdates(docs: TldrawDrawing[]): Buffer[] { - if (!Array.isArray(docs) || !docs.length) return []; + private convertMongoUpdates(tldrawDrawingEntities: TldrawDrawing[]): Buffer[] { + if (!Array.isArray(tldrawDrawingEntities) || !tldrawDrawingEntities.length) return []; const updates: Buffer[] = []; - for (let i = 0; i < docs.length; i += 1) { - const doc = docs[i]; + for (let i = 0; i < tldrawDrawingEntities.length; i += 1) { + const tldrawDrawingEntity = tldrawDrawingEntities[i]; - if (!doc.part) { - updates.push(Buffer.from(doc.value.buffer)); + if (!tldrawDrawingEntity.part) { + updates.push(Buffer.from(tldrawDrawingEntity.value.buffer)); } - if (doc.part === 1) { + if (tldrawDrawingEntity.part === 1) { // merge the docs together that got split because of mongodb size limits - const parts = this.mergeDocsTogether(doc, docs, i); + const parts = this.mergeDocsTogether(tldrawDrawingEntity, tldrawDrawingEntities, i); updates.push(Buffer.concat(parts)); } } @@ -189,10 +200,19 @@ export class YMongodb { * Get all document updates for a specific document. */ private async getMongoUpdates(docName: string, opts = {}): Promise { + performance.mark('getMongoUpdates'); + const uniqueKey = KeyFactory.createForUpdate(docName); - const docs = await this.getMongoBulkData(uniqueKey, opts); + const tldrawDrawingEntities = await this.getMongoBulkData(uniqueKey, opts); + + const buffer = this.convertMongoUpdates(tldrawDrawingEntities); + + performance.measure('tldraw:YMongodb:getMongoUpdates', { + start: 'getMongoUpdates', + detail: { doc_name: docName, loaded_tldraw_entities_total: tldrawDrawingEntities.length }, + }); - return this.convertMongoUpdates(docs); + return buffer; } private async writeStateVector(docName: string, sv: Uint8Array, clock: number): Promise { @@ -247,20 +267,23 @@ export class YMongodb { return clock + 1; } - private isSameClock(doc1: TldrawDrawing, doc2: TldrawDrawing): boolean { - return doc1.clock === doc2.clock; + private isSameClock(tldrawDrawingEntity1: TldrawDrawing, tldrawDrawingEntity2: TldrawDrawing): boolean { + return tldrawDrawingEntity1.clock === tldrawDrawingEntity2.clock; } - private checkIfPartIsNextPartAfterCurrent(part: TldrawDrawing, currentPartId: number | undefined): void { - if (part.part === undefined || currentPartId !== part.part - 1) { + private checkIfPartIsNextPartAfterCurrent( + tldrawDrawingEntity: TldrawDrawing, + currentPartId: number | undefined + ): void { + if (tldrawDrawingEntity.part === undefined || currentPartId !== tldrawDrawingEntity.part - 1) { throw new Error('Could not merge updates together because a part is missing'); } } - private extractClock(updates: TldrawDrawing[]): number { - if (updates.length === 0 || updates[0].clock == null) { + private extractClock(tldrawDrawingEntities: TldrawDrawing[]): number { + if (tldrawDrawingEntities.length === 0 || tldrawDrawingEntities[0].clock == null) { return -1; } - return updates[0].clock; + return tldrawDrawingEntities[0].clock; } } diff --git a/apps/server/src/modules/tldraw/service/tldraw.ws.service.spec.ts b/apps/server/src/modules/tldraw/service/tldraw.ws.service.spec.ts index 50b19dca282..61853806003 100644 --- a/apps/server/src/modules/tldraw/service/tldraw.ws.service.spec.ts +++ b/apps/server/src/modules/tldraw/service/tldraw.ws.service.spec.ts @@ -1,29 +1,29 @@ -import { Test } from '@nestjs/testing'; +import { createMock, DeepMocked } from '@golevelup/ts-jest'; +import { MongoMemoryDatabaseModule } from '@infra/database'; +import { HttpService } from '@nestjs/axios'; import { INestApplication } from '@nestjs/common'; -import WebSocket from 'ws'; +import { ConfigModule } from '@nestjs/config'; import { WsAdapter } from '@nestjs/platform-ws'; -import { TextEncoder } from 'util'; -import * as Yjs from 'yjs'; -import * as SyncProtocols from 'y-protocols/sync'; -import * as AwarenessProtocol from 'y-protocols/awareness'; -import * as Ioredis from 'ioredis'; -import { encoding } from 'lib0'; -import { TldrawWsFactory } from '@shared/testing/factory/tldraw.ws.factory'; -import { HttpService } from '@nestjs/axios'; +import { Test } from '@nestjs/testing'; import { WebSocketReadyStateEnum } from '@shared/testing'; -import { createMock, DeepMocked } from '@golevelup/ts-jest'; -import { ConfigModule } from '@nestjs/config'; +import { TldrawWsFactory } from '@shared/testing/factory/tldraw.ws.factory'; import { createConfigModuleOptions } from '@src/config'; -import { MongoMemoryDatabaseModule } from '@infra/database'; import { DomainErrorHandler } from '@src/core'; -import { TldrawRedisFactory, TldrawRedisService } from '../redis'; +import * as Ioredis from 'ioredis'; +import { encoding } from 'lib0'; +import { TextEncoder } from 'util'; +import WebSocket from 'ws'; +import * as AwarenessProtocol from 'y-protocols/awareness'; +import * as SyncProtocols from 'y-protocols/sync'; +import * as Yjs from 'yjs'; +import { TldrawWsService } from '.'; import { TldrawWs } from '../controller'; +import { WsSharedDocDo } from '../domain'; import { TldrawDrawing } from '../entities'; +import { MetricsService } from '../metrics'; +import { TldrawRedisFactory, TldrawRedisService } from '../redis'; import { TldrawBoardRepo, TldrawRepo, YMongodb } from '../repo'; import { TestConnection, tldrawTestConfig } from '../testing'; -import { WsSharedDocDo } from '../domain'; -import { MetricsService } from '../metrics'; -import { TldrawWsService } from '.'; jest.mock('yjs', () => { const moduleMock: unknown = { diff --git a/apps/server/src/modules/tldraw/service/tldraw.ws.service.ts b/apps/server/src/modules/tldraw/service/tldraw.ws.service.ts index 82deaf6ac3c..1fadacf0bfd 100644 --- a/apps/server/src/modules/tldraw/service/tldraw.ws.service.ts +++ b/apps/server/src/modules/tldraw/service/tldraw.ws.service.ts @@ -1,31 +1,23 @@ import { Injectable, NotAcceptableException } from '@nestjs/common'; import { ConfigService } from '@nestjs/config'; +import { DomainErrorHandler } from '@src/core'; +import { decoding, encoding } from 'lib0'; +import { Buffer } from 'node:buffer'; import WebSocket from 'ws'; import { encodeAwarenessUpdate, removeAwarenessStates } from 'y-protocols/awareness'; -import { decoding, encoding } from 'lib0'; import { readSyncMessage, writeSyncStep1, writeSyncStep2, writeUpdate } from 'y-protocols/sync'; -import { Buffer } from 'node:buffer'; -import { YMap } from 'yjs/dist/src/types/YMap'; -import { DomainErrorHandler } from '@src/core'; -import { TldrawRedisService } from '../redis'; +import { TldrawConfig } from '../config'; +import { WsSharedDocDo } from '../domain'; import { CloseConnectionLoggable, WebsocketErrorLoggable, WebsocketMessageErrorLoggable, WsSharedDocErrorLoggable, } from '../loggable'; -import { TldrawConfig } from '../config'; -import { - AwarenessConnectionsUpdate, - TldrawAsset, - TldrawShape, - UpdateOrigin, - UpdateType, - WSMessageType, -} from '../types'; -import { WsSharedDocDo } from '../domain'; -import { TldrawBoardRepo } from '../repo'; import { MetricsService } from '../metrics'; +import { TldrawRedisService } from '../redis'; +import { TldrawBoardRepo } from '../repo'; +import { AwarenessConnectionsUpdate, UpdateOrigin, UpdateType, WSMessageType } from '../types'; @Injectable() export class TldrawWsService { @@ -42,6 +34,8 @@ export class TldrawWsService { } public async closeConnection(doc: WsSharedDocDo, ws: WebSocket): Promise { + performance.mark('closeConnection'); + if (doc.connections.has(ws)) { const controlledIds = doc.connections.get(ws); doc.connections.delete(ws); @@ -52,6 +46,11 @@ export class TldrawWsService { ws.close(); await this.finalizeIfNoConnections(doc); + + performance.measure('tldraw:TldrawWsService:closeConnection', { + start: 'closeConnection', + detail: { doc_name: doc.name, doc_connection_total: doc.connections.size }, + }); } public send(doc: WsSharedDocDo, ws: WebSocket, message: Uint8Array): void { @@ -179,6 +178,8 @@ export class TldrawWsService { }; public async setupWsConnection(ws: WebSocket, docName: string): Promise { + performance.mark('setupWsConnection'); + ws.binaryType = 'arraybuffer'; // get doc, initialize if it does not exist yet - update this.getDocument(docName) can be return null @@ -224,27 +225,36 @@ export class TldrawWsService { pongReceived = true; }); - { - // send initial doc state to client as update - this.sendInitialState(ws, doc); - - const syncEncoder = encoding.createEncoder(); - encoding.writeVarUint(syncEncoder, WSMessageType.SYNC); - writeSyncStep1(syncEncoder, doc); - this.send(doc, ws, encoding.toUint8Array(syncEncoder)); - - const awarenessStates = doc.awareness.getStates(); - if (awarenessStates.size > 0) { - const awarenessEncoder = encoding.createEncoder(); - encoding.writeVarUint(awarenessEncoder, WSMessageType.AWARENESS); - encoding.writeVarUint8Array( - awarenessEncoder, - encodeAwarenessUpdate(doc.awareness, Array.from(awarenessStates.keys())) - ); - this.send(doc, ws, encoding.toUint8Array(awarenessEncoder)); - } + // send initial doc state to client as update + this.sendInitialState(ws, doc); + + const syncEncoder = encoding.createEncoder(); + encoding.writeVarUint(syncEncoder, WSMessageType.SYNC); + writeSyncStep1(syncEncoder, doc); + this.send(doc, ws, encoding.toUint8Array(syncEncoder)); + + const awarenessStates = doc.awareness.getStates(); + if (awarenessStates.size > 0) { + const awarenessEncoder = encoding.createEncoder(); + encoding.writeVarUint(awarenessEncoder, WSMessageType.AWARENESS); + encoding.writeVarUint8Array( + awarenessEncoder, + encodeAwarenessUpdate(doc.awareness, Array.from(awarenessStates.keys())) + ); + this.send(doc, ws, encoding.toUint8Array(awarenessEncoder)); } + this.metricsService.incrementNumberOfUsersOnServerCounter(); + + performance.measure('tldraw:TldrawWsService:setupWsConnection', { + start: 'setupWsConnection', + detail: { + doc_name: doc.name, + doc_awareness_state_total: awarenessStates.size, + doc_connection_total: doc.connections.size, + pod_docs_total: this.docs.size, + }, + }); } private async finalizeIfNoConnections(doc: WsSharedDocDo) { @@ -274,34 +284,6 @@ export class TldrawWsService { } } - private syncDocumentAssetsWithShapes(doc: WsSharedDocDo): TldrawAsset[] { - // clean up assets that are not used as shapes anymore - // which can happen when users do undo/redo operations on assets - const assets: YMap = doc.getMap('assets'); - const shapes: YMap = doc.getMap('shapes'); - const usedShapesAsAssets: TldrawShape[] = []; - const usedAssets: TldrawAsset[] = []; - - for (const [, shape] of shapes) { - if (shape.assetId) { - usedShapesAsAssets.push(shape); - } - } - - doc.transact(() => { - for (const [, asset] of assets) { - const foundAsset = usedShapesAsAssets.some((shape) => shape.assetId === asset.id); - if (!foundAsset) { - assets.delete(asset.id); - } else { - usedAssets.push(asset); - } - } - }); - - return usedAssets; - } - private sendUpdateToConnectedClients(update: Uint8Array, doc: WsSharedDocDo): void { const encoder = encoding.createEncoder(); encoding.writeVarUint(encoder, WSMessageType.SYNC); diff --git a/apps/server/src/modules/tldraw/tldraw-console.module.ts b/apps/server/src/modules/tldraw/tldraw-console.module.ts index fb3260def02..80cddece592 100644 --- a/apps/server/src/modules/tldraw/tldraw-console.module.ts +++ b/apps/server/src/modules/tldraw/tldraw-console.module.ts @@ -3,13 +3,14 @@ import { RabbitMQWrapperModule } from '@infra/rabbitmq'; import { Dictionary, IPrimaryKey } from '@mikro-orm/core'; import { MikroOrmModule, MikroOrmModuleSyncOptions } from '@mikro-orm/nestjs'; import { Module, NotFoundException } from '@nestjs/common'; -import { ConfigModule } from '@nestjs/config'; -import { DB_PASSWORD, DB_USERNAME, createConfigModuleOptions } from '@src/config'; +import { ConfigModule, ConfigService } from '@nestjs/config'; +import { initialisePerformanceObserver } from '@shared/common/measure-utils'; +import { createConfigModuleOptions, DB_PASSWORD, DB_USERNAME } from '@src/config'; import { CoreModule } from '@src/core'; -import { LoggerModule } from '@src/core/logger'; +import { Logger, LoggerModule } from '@src/core/logger'; import { ConsoleModule } from 'nestjs-console'; import { FilesStorageClientModule } from '../files-storage-client'; -import { TLDRAW_DB_URL, config } from './config'; +import { config, TldrawConfig, TLDRAW_DB_URL } from './config'; import { TldrawDrawing } from './entities'; import { TldrawFilesConsole } from './job'; import { TldrawRepo, YMongodb } from './repo'; @@ -24,6 +25,7 @@ const defaultMikroOrmOptions: MikroOrmModuleSyncOptions = { @Module({ imports: [ + CoreModule, ConsoleModule, ConsoleWriterModule, RabbitMQWrapperModule, @@ -42,4 +44,11 @@ const defaultMikroOrmOptions: MikroOrmModuleSyncOptions = { ], providers: [TldrawRepo, YMongodb, TldrawFilesConsole, TldrawFilesStorageAdapterService, TldrawDeleteFilesUc], }) -export class TldrawConsoleModule {} +export class TldrawConsoleModule { + constructor(private readonly logger: Logger, private readonly configService: ConfigService) { + if (this.configService.get('PERFORMANCE_MEASURE_ENABLED') === true) { + this.logger.setContext('PerformanceObserver'); + initialisePerformanceObserver(this.logger); + } + } +} diff --git a/apps/server/src/modules/tldraw/tldraw-ws.module.ts b/apps/server/src/modules/tldraw/tldraw-ws.module.ts index 3f096352a4a..a4d7ba2ede6 100644 --- a/apps/server/src/modules/tldraw/tldraw-ws.module.ts +++ b/apps/server/src/modules/tldraw/tldraw-ws.module.ts @@ -1,18 +1,19 @@ +import { Dictionary, IPrimaryKey } from '@mikro-orm/core'; +import { MikroOrmModule, MikroOrmModuleSyncOptions } from '@mikro-orm/nestjs'; +import { HttpModule } from '@nestjs/axios'; import { Module, NotFoundException } from '@nestjs/common'; -import { ConfigModule } from '@nestjs/config'; +import { ConfigModule, ConfigService } from '@nestjs/config'; +import { initialisePerformanceObserver } from '@shared/common/measure-utils'; import { createConfigModuleOptions, DB_PASSWORD, DB_USERNAME } from '@src/config'; import { CoreModule } from '@src/core'; -import { LoggerModule } from '@src/core/logger'; -import { MikroOrmModule, MikroOrmModuleSyncOptions } from '@mikro-orm/nestjs'; -import { Dictionary, IPrimaryKey } from '@mikro-orm/core'; -import { HttpModule } from '@nestjs/axios'; +import { Logger, LoggerModule } from '@src/core/logger'; +import { config, TldrawConfig, TLDRAW_DB_URL } from './config'; +import { TldrawWs } from './controller'; import { TldrawDrawing } from './entities'; import { MetricsService } from './metrics'; +import { TldrawRedisFactory, TldrawRedisService } from './redis'; import { TldrawBoardRepo, TldrawRepo, YMongodb } from './repo'; import { TldrawWsService } from './service'; -import { TldrawWs } from './controller'; -import { config, TLDRAW_DB_URL } from './config'; -import { TldrawRedisFactory, TldrawRedisService } from './redis'; const defaultMikroOrmOptions: MikroOrmModuleSyncOptions = { findOneOrFailHandler: (entityName: string, where: Dictionary | IPrimaryKey) => @@ -45,4 +46,11 @@ const defaultMikroOrmOptions: MikroOrmModuleSyncOptions = { TldrawRedisService, ], }) -export class TldrawWsModule {} +export class TldrawWsModule { + constructor(private readonly logger: Logger, private readonly configService: ConfigService) { + if (this.configService.get('PERFORMANCE_MEASURE_ENABLED') === true) { + this.logger.setContext('PerformanceObserver'); + initialisePerformanceObserver(this.logger); + } + } +} diff --git a/apps/server/src/shared/common/error/index.ts b/apps/server/src/shared/common/error/index.ts index d82dbc40fbb..58446694939 100644 --- a/apps/server/src/shared/common/error/index.ts +++ b/apps/server/src/shared/common/error/index.ts @@ -4,6 +4,7 @@ export * from './business.error'; export * from './entity-not-found.error'; export * from './forbidden-operation.error'; export * from './validation.error'; +export * from './interfaces'; // business errors export * from './user-already-assigned-to-import-user.business-error'; diff --git a/apps/server/src/shared/common/error/interfaces.ts b/apps/server/src/shared/common/error/interfaces.ts new file mode 100644 index 00000000000..e9f58d88279 --- /dev/null +++ b/apps/server/src/shared/common/error/interfaces.ts @@ -0,0 +1,12 @@ +export type ErrorLogMessage = { + error?: Error; + type: string; // TODO: use enum + stack?: string; + data?: { [key: string]: string | number | boolean | undefined }; +}; + +export type ValidationErrorLogMessage = { + validationErrors: string[]; + stack?: string; + type: string; // TODO: use enum +}; diff --git a/apps/server/src/shared/common/loggable/index.ts b/apps/server/src/shared/common/loggable/index.ts index 5f21a462625..41cf4b21ac5 100644 --- a/apps/server/src/shared/common/loggable/index.ts +++ b/apps/server/src/shared/common/loggable/index.ts @@ -1 +1,2 @@ export { ReferencedEntityNotFoundLoggable } from './referenced-entity-not-found-loggable'; +export { Loggable, LoggableMessage } from './interfaces'; diff --git a/apps/server/src/shared/common/loggable/interfaces.ts b/apps/server/src/shared/common/loggable/interfaces.ts new file mode 100644 index 00000000000..359b5f37ad9 --- /dev/null +++ b/apps/server/src/shared/common/loggable/interfaces.ts @@ -0,0 +1,18 @@ +import { ErrorLogMessage, ValidationErrorLogMessage } from '../error'; + +type LogMessageDataObject = { + [key: string]: LogMessageData; +}; + +type LogMessageData = LogMessageDataObject | string | number | boolean | undefined; + +type LogMessage = { + message: string; + data?: LogMessageData; +}; + +export type LoggableMessage = LogMessage | ErrorLogMessage | ValidationErrorLogMessage; + +export interface Loggable { + getLogMessage(): LoggableMessage; +} diff --git a/apps/server/src/shared/common/loggable/referenced-entity-not-found-loggable.ts b/apps/server/src/shared/common/loggable/referenced-entity-not-found-loggable.ts index 10031eeb67e..2a6e33c97ff 100644 --- a/apps/server/src/shared/common/loggable/referenced-entity-not-found-loggable.ts +++ b/apps/server/src/shared/common/loggable/referenced-entity-not-found-loggable.ts @@ -1,5 +1,5 @@ -import { ErrorLogMessage, Loggable, LogMessage, ValidationErrorLogMessage } from '@src/core/logger'; import { EntityId } from '../../domain/types'; +import { Loggable, LoggableMessage } from './interfaces'; export class ReferencedEntityNotFoundLoggable implements Loggable { constructor( @@ -9,7 +9,7 @@ export class ReferencedEntityNotFoundLoggable implements Loggable { private readonly referencedEntityId: EntityId ) {} - getLogMessage(): LogMessage | ErrorLogMessage | ValidationErrorLogMessage { + getLogMessage(): LoggableMessage { return { message: 'The requested entity could not been found, but it is still referenced.', data: { diff --git a/apps/server/src/shared/common/measure-utils/index.ts b/apps/server/src/shared/common/measure-utils/index.ts new file mode 100644 index 00000000000..e217f54ad43 --- /dev/null +++ b/apps/server/src/shared/common/measure-utils/index.ts @@ -0,0 +1 @@ +export * from './performance-observer'; diff --git a/apps/server/src/shared/common/measure-utils/performance-observer.spec.ts b/apps/server/src/shared/common/measure-utils/performance-observer.spec.ts new file mode 100644 index 00000000000..668ffc7ff29 --- /dev/null +++ b/apps/server/src/shared/common/measure-utils/performance-observer.spec.ts @@ -0,0 +1,103 @@ +import { PerformanceEntry } from 'node:perf_hooks'; +import { + InitialisePerformanceObserverLoggable, + MeasuresLoggable, + initialisePerformanceObserver, + closePerformanceObserver, +} from './performance-observer'; + +async function wait(timeoutMS: number): Promise { + return new Promise((resolve) => { + setTimeout(resolve, timeoutMS); + }); +} + +async function waitForEventLoopEnd(): Promise { + return new Promise((resolve) => { + process.nextTick(() => { + resolve(); + }); + }); +} + +describe('PerformanceObserver', () => { + afterEach(() => { + jest.restoreAllMocks(); + }); + + describe('InitialisePerformanceObserverLoggable', () => { + describe('getLogMessage', () => { + it('should be log correct formated message', () => { + const loggable = new InitialisePerformanceObserverLoggable(); + + const log = loggable.getLogMessage(); + + expect(log).toEqual({ + message: 'Initialise PerformanceObserver...', + }); + }); + }); + }); + + describe('MeasuresLoggable', () => { + describe('getLogMessage', () => { + const setup = () => { + const performanceEntry = { name: 'a', duration: 1, detail: { x: 1 } } as PerformanceEntry; + + const loggable = new MeasuresLoggable([performanceEntry, performanceEntry]); + + return { loggable }; + }; + + it('should be log correct formated message', () => { + const { loggable } = setup(); + + const log = loggable.getLogMessage(); + + expect(log).toEqual({ + message: 'Measure results', + data: '[{ location: a, duration: 1, detail: { x: 1 } }, { location: a, duration: 1, detail: { x: 1 } }]', + }); + }); + }); + }); + + describe('initialisePerformanceObserver', () => { + const setup = () => { + const mockInfoLogger = { + info: () => {}, + }; + const infoLoggerSpy = jest.spyOn(mockInfoLogger, 'info'); + + return { infoLoggerSpy, mockInfoLogger }; + }; + + it('should be log by execution', () => { + const { infoLoggerSpy, mockInfoLogger } = setup(); + + initialisePerformanceObserver(mockInfoLogger); + + expect(infoLoggerSpy).toHaveBeenNthCalledWith(1, new InitialisePerformanceObserverLoggable()); + + closePerformanceObserver(); + }); + + it('should be log messure if it is executed', async () => { + const { infoLoggerSpy, mockInfoLogger } = setup(); + initialisePerformanceObserver(mockInfoLogger); + infoLoggerSpy.mockClear(); + + performance.mark('startMark'); + await wait(1); + performance.measure('myMeasure', { + start: 'startMark', + detail: { x: 1 }, + }); + + await waitForEventLoopEnd(); + expect(infoLoggerSpy).toHaveBeenNthCalledWith(1, new MeasuresLoggable([])); + + closePerformanceObserver(); + }); + }); +}); diff --git a/apps/server/src/shared/common/measure-utils/performance-observer.ts b/apps/server/src/shared/common/measure-utils/performance-observer.ts new file mode 100644 index 00000000000..6b052b0fd3a --- /dev/null +++ b/apps/server/src/shared/common/measure-utils/performance-observer.ts @@ -0,0 +1,56 @@ +import { PerformanceEntry, PerformanceObserver } from 'node:perf_hooks'; +import util from 'util'; +import { Loggable, LoggableMessage } from '../loggable'; + +interface InfoLogger { + info(input: Loggable): void; +} + +export class MeasuresLoggable implements Loggable { + constructor(private readonly entries: PerformanceEntry[]) {} + + getLogMessage(): LoggableMessage { + const stringifiedEntries = this.entries.map((entry) => { + const detail = util.inspect(entry.detail).replace(/\n/g, '').replace(/\\n/g, ''); + return `{ location: ${entry.name}, duration: ${entry.duration}, detail: ${detail} }`; + }); + const data = `[${stringifiedEntries.join(', ')}]`; + const message = { message: `Measure results`, data }; + + return message; + } +} + +export class InitialisePerformanceObserverLoggable implements Loggable { + getLogMessage(): LoggableMessage { + return { + message: 'Initialise PerformanceObserver...', + }; + } +} + +let observer: PerformanceObserver | null = null; + +export const initialisePerformanceObserver = (infoLogger: InfoLogger): PerformanceObserver => { + infoLogger.info(new InitialisePerformanceObserverLoggable()); + + if (observer === null) { + observer = new PerformanceObserver((perfObserverEntryList) => { + const entries = perfObserverEntryList.getEntriesByType('measure'); + infoLogger.info(new MeasuresLoggable(entries)); + }); + + observer.observe({ type: 'measure', buffered: true }); + } + + return observer; +}; + +export const closePerformanceObserver = (): void => { + if (observer !== null) { + performance.clearMarks(); + performance.clearMeasures(); + observer.disconnect(); + observer = null; + } +}; diff --git a/config/default.schema.json b/config/default.schema.json index 5622b162ee8..4e17feb039d 100644 --- a/config/default.schema.json +++ b/config/default.schema.json @@ -1577,6 +1577,17 @@ "type": "string", "description": "List with allowed assets MIME types, comma separated, empty if all MIME types supported by tldraw should be allowed", "examples": ["image/gif,image/jpeg,video/webm"] + }, + "PERFORMANCE_MEASURE_ENABLED": { + "type": "boolean", + "description": "Activate the performance measure for observed areas.", + "default": true + }, + "LOG_LEVEL": { + "type": "string", + "default": "info", + "description": "Define log level for tldraw.", + "enum": ["emerg", "alert", "crit", "error", "warning", "notice", "info", "debug"] } }, "default": {