From a670c93ff28640180b3a9e91c2f4dbd115591983 Mon Sep 17 00:00:00 2001 From: Cedric Evers <12080057+CeEv@users.noreply.github.com> Date: Tue, 18 Jun 2024 16:03:18 +0200 Subject: [PATCH 01/28] Add initial PerformanceObserver and use it. --- .../src/core/logger/interfaces/loggable.ts | 1 + .../src/core/logger/types/logging.types.ts | 3 + apps/server/src/modules/tldraw/config.ts | 2 + .../src/modules/tldraw/repo/y-mongodb.ts | 25 ++++++-- .../tldraw/service/tldraw.ws.service.ts | 29 ++++++++- apps/server/src/shared/common/error/index.ts | 1 + .../src/shared/common/error/interfaces.ts | 12 ++++ .../src/shared/common/loggable/index.ts | 1 + .../src/shared/common/loggable/interfaces.ts | 18 ++++++ .../referenced-entity-not-found-loggable.ts | 4 +- .../src/shared/common/measure-utils/index.ts | 1 + .../measure-utils/performance-observer.ts | 64 +++++++++++++++++++ config/default.schema.json | 5 ++ 13 files changed, 157 insertions(+), 9 deletions(-) create mode 100644 apps/server/src/shared/common/error/interfaces.ts create mode 100644 apps/server/src/shared/common/loggable/interfaces.ts create mode 100644 apps/server/src/shared/common/measure-utils/index.ts create mode 100644 apps/server/src/shared/common/measure-utils/performance-observer.ts diff --git a/apps/server/src/core/logger/interfaces/loggable.ts b/apps/server/src/core/logger/interfaces/loggable.ts index 005a7f8efe8..7b23494a622 100644 --- a/apps/server/src/core/logger/interfaces/loggable.ts +++ b/apps/server/src/core/logger/interfaces/loggable.ts @@ -1,5 +1,6 @@ import { ErrorLogMessage, LogMessage, ValidationErrorLogMessage } from '../types'; +// should be in shared or? export interface Loggable { getLogMessage(): LogMessage | ErrorLogMessage | ValidationErrorLogMessage; } diff --git a/apps/server/src/core/logger/types/logging.types.ts b/apps/server/src/core/logger/types/logging.types.ts index 5271ba85338..851f748cabe 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..1fdb3eae5e4 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; @@ -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.ts b/apps/server/src/modules/tldraw/repo/y-mongodb.ts index 1ff357bba1c..19d1bfe5649 100644 --- a/apps/server/src/modules/tldraw/repo/y-mongodb.ts +++ b/apps/server/src/modules/tldraw/repo/y-mongodb.ts @@ -1,5 +1,5 @@ import { BulkWriteResult } from '@mikro-orm/mongodb/node_modules/mongodb'; -import { Injectable } from '@nestjs/common'; +import { Injectable, OnModuleInit } from '@nestjs/common'; import { ConfigService } from '@nestjs/config'; import { Buffer } from 'buffer'; import * as binary from 'lib0/binary'; @@ -7,6 +7,8 @@ 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 { initilisedPerformanceObserver } from '@shared/common/measure-utils'; +import { Logger } from '@src/core/logger'; import { TldrawConfig } from '../config'; import { WsSharedDocDo } from '../domain'; import { TldrawDrawing } from '../entities'; @@ -16,7 +18,7 @@ import { KeyFactory, Version } from './key.factory'; import { TldrawRepo } from './tldraw.repo'; @Injectable() -export class YMongodb { +export class YMongodb implements OnModuleInit { private readonly _transact: >(docName: string, fn: () => T) => T; // scope the queue of the transaction to each docName @@ -26,7 +28,8 @@ export class YMongodb { constructor( private readonly configService: ConfigService, private readonly repo: TldrawRepo, - private readonly domainErrorHandler: DomainErrorHandler + private readonly domainErrorHandler: DomainErrorHandler, + private readonly logger: Logger ) { // execute a transaction on a database // this will ensure that other processes are currently not writing @@ -62,6 +65,12 @@ export class YMongodb { }; } + onModuleInit() { + if (this.configService.get('PERFORMANCE_MEASURE_ENABLED') === true) { + initilisedPerformanceObserver(this.logger); + } + } + public async createIndex(): Promise { await this.repo.ensureIndexes(); } @@ -94,7 +103,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 - start'); + return this._transact(docName, async () => { const updates = await this.getMongoUpdates(docName); const mergedUpdates = mergeUpdates(updates); @@ -105,10 +115,17 @@ 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.mark('compressDocumentTransactional - end'); + performance.measure( + `tldraw:YMongodb:compressDocumentTransactional::${docName}`, + 'compressDocumentTransactional - start', + 'compressDocumentTransactional - end' + ); }); } 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..0038ae7062c 100644 --- a/apps/server/src/modules/tldraw/service/tldraw.ws.service.ts +++ b/apps/server/src/modules/tldraw/service/tldraw.ws.service.ts @@ -1,4 +1,4 @@ -import { Injectable, NotAcceptableException } from '@nestjs/common'; +import { Injectable, NotAcceptableException, OnModuleInit } from '@nestjs/common'; import { ConfigService } from '@nestjs/config'; import WebSocket from 'ws'; import { encodeAwarenessUpdate, removeAwarenessStates } from 'y-protocols/awareness'; @@ -7,6 +7,8 @@ import { readSyncMessage, writeSyncStep1, writeSyncStep2, writeUpdate } from 'y- import { Buffer } from 'node:buffer'; import { YMap } from 'yjs/dist/src/types/YMap'; import { DomainErrorHandler } from '@src/core'; +import { Logger } from '@src/core/logger'; +import { initilisedPerformanceObserver } from '@shared/common/measure-utils'; import { TldrawRedisService } from '../redis'; import { CloseConnectionLoggable, @@ -28,7 +30,7 @@ import { TldrawBoardRepo } from '../repo'; import { MetricsService } from '../metrics'; @Injectable() -export class TldrawWsService { +export class TldrawWsService implements OnModuleInit { public docs = new Map(); constructor( @@ -36,12 +38,20 @@ export class TldrawWsService { private readonly tldrawBoardRepo: TldrawBoardRepo, private readonly domainErrorHandler: DomainErrorHandler, private readonly metricsService: MetricsService, - private readonly tldrawRedisService: TldrawRedisService + private readonly tldrawRedisService: TldrawRedisService, + private readonly logger: Logger ) { this.tldrawRedisService.sub.on('messageBuffer', (channel, message) => this.redisMessageHandler(channel, message)); } + onModuleInit() { + if (this.configService.get('PERFORMANCE_MEASURE_ENABLED') === true) { + initilisedPerformanceObserver(this.logger); + } + } + public async closeConnection(doc: WsSharedDocDo, ws: WebSocket): Promise { + performance.mark('closeConnection - start'); if (doc.connections.has(ws)) { const controlledIds = doc.connections.get(ws); doc.connections.delete(ws); @@ -52,6 +62,12 @@ export class TldrawWsService { ws.close(); await this.finalizeIfNoConnections(doc); + performance.mark('closeConnection - end'); + performance.measure( + `tldraw:TldrawWsService:closeConnection::${doc.name}`, + 'closeConnection - start', + 'closeConnection - end' + ); } public send(doc: WsSharedDocDo, ws: WebSocket, message: Uint8Array): void { @@ -181,9 +197,16 @@ export class TldrawWsService { public async setupWsConnection(ws: WebSocket, docName: string): Promise { ws.binaryType = 'arraybuffer'; + performance.mark('get document - start'); // get doc, initialize if it does not exist yet - update this.getDocument(docName) can be return null const doc = await this.getDocument(docName); doc.connections.set(ws, new Set()); + performance.mark('ws connection to doc - done'); + performance.measure( + `tldraw:TldrawWsService:setupWsConnection::${docName}`, + 'get document - start', + 'ws connection to doc - done' + ); ws.on('error', (err) => { this.domainErrorHandler.exec(new WebsocketErrorLoggable(err)); 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.ts b/apps/server/src/shared/common/measure-utils/performance-observer.ts new file mode 100644 index 00000000000..bcc4299b4e4 --- /dev/null +++ b/apps/server/src/shared/common/measure-utils/performance-observer.ts @@ -0,0 +1,64 @@ +import { PerformanceObserver, PerformanceEntry } from 'node:perf_hooks'; +import { Loggable, LoggableMessage } from '../loggable'; + +interface InfoLogger { + info(input: Loggable): void; +} + +class MeasureLoggable implements Loggable { + entries: PerformanceEntry[] = []; + + constructor(entries: PerformanceEntry[]) { + this.entries = entries; + } + + getLogMessage(): LoggableMessage { + const data = JSON.stringify(this.entries); + + return { + message: 'Measure result', + data, + }; + } +} + +class InitalisePerformanceLogger implements Loggable { + getLogMessage(): LoggableMessage { + return { + message: 'Initialise PerformanceObserver...', + }; + } +} + +let obs: PerformanceObserver | null = null; + +/** + * Please note after adding the observer is avaible on the complet node process. + * This can be add in constructor of a class, in best case with feature flag. To add it or not. + * After it the messaure can be used with: + * performance.mark to create pointer and performance.messure to generate a delta between marks + * + * performance.mark('compressDocumentTransactional - start'); + * // code to messure + * performance.mark('compressDocumentTransactional - end'); + * + * performance.measure( + * `tldraw:YMongodb:compressDocumentTransactional::${docName}`, + * 'compressDocumentTransactional - start', + * 'compressDocumentTransactional - end' + * ); + */ +export const initilisedPerformanceObserver = (infoLogger: InfoLogger): PerformanceObserver => { + if (obs === null) { + infoLogger.info(new InitalisePerformanceLogger()); + // eslint-disable-next-line @typescript-eslint/no-unused-vars + obs = new PerformanceObserver((perfObserverList, observer) => { + const entries = perfObserverList.getEntries(); + const loggable = new MeasureLoggable(entries); + infoLogger.info(loggable); + }); + obs.observe({ type: 'measure', buffered: true }); + } + + return obs; +}; diff --git a/config/default.schema.json b/config/default.schema.json index 743bfe41711..d20ce638db7 100644 --- a/config/default.schema.json +++ b/config/default.schema.json @@ -1577,6 +1577,11 @@ "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 overserved areas.", + "default": true } }, "default": { From 7edc6902d3b92a8df5efff2b10e0fdc2ab1052b4 Mon Sep 17 00:00:00 2001 From: Cedric Evers <12080057+CeEv@users.noreply.github.com> Date: Tue, 18 Jun 2024 17:06:20 +0200 Subject: [PATCH 02/28] change used log level to alert --- .../shared/common/measure-utils/performance-observer.ts | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/apps/server/src/shared/common/measure-utils/performance-observer.ts b/apps/server/src/shared/common/measure-utils/performance-observer.ts index bcc4299b4e4..d90595e9021 100644 --- a/apps/server/src/shared/common/measure-utils/performance-observer.ts +++ b/apps/server/src/shared/common/measure-utils/performance-observer.ts @@ -2,6 +2,7 @@ import { PerformanceObserver, PerformanceEntry } from 'node:perf_hooks'; import { Loggable, LoggableMessage } from '../loggable'; interface InfoLogger { + alert(input: Loggable): void; info(input: Loggable): void; } @@ -22,7 +23,7 @@ class MeasureLoggable implements Loggable { } } -class InitalisePerformanceLogger implements Loggable { +class InitalisePerformanceLoggable implements Loggable { getLogMessage(): LoggableMessage { return { message: 'Initialise PerformanceObserver...', @@ -50,12 +51,12 @@ let obs: PerformanceObserver | null = null; */ export const initilisedPerformanceObserver = (infoLogger: InfoLogger): PerformanceObserver => { if (obs === null) { - infoLogger.info(new InitalisePerformanceLogger()); + infoLogger.alert(new InitalisePerformanceLoggable()); // eslint-disable-next-line @typescript-eslint/no-unused-vars obs = new PerformanceObserver((perfObserverList, observer) => { const entries = perfObserverList.getEntries(); const loggable = new MeasureLoggable(entries); - infoLogger.info(loggable); + infoLogger.alert(loggable); }); obs.observe({ type: 'measure', buffered: true }); } From 56f0a78abc90c27b8aa3765626502318efbf7a9b Mon Sep 17 00:00:00 2001 From: Cedric Evers <12080057+CeEv@users.noreply.github.com> Date: Tue, 18 Jun 2024 17:15:18 +0200 Subject: [PATCH 03/28] Revert last commit --- .../src/shared/common/measure-utils/performance-observer.ts | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/apps/server/src/shared/common/measure-utils/performance-observer.ts b/apps/server/src/shared/common/measure-utils/performance-observer.ts index d90595e9021..270f297b73a 100644 --- a/apps/server/src/shared/common/measure-utils/performance-observer.ts +++ b/apps/server/src/shared/common/measure-utils/performance-observer.ts @@ -2,7 +2,6 @@ import { PerformanceObserver, PerformanceEntry } from 'node:perf_hooks'; import { Loggable, LoggableMessage } from '../loggable'; interface InfoLogger { - alert(input: Loggable): void; info(input: Loggable): void; } @@ -51,12 +50,12 @@ let obs: PerformanceObserver | null = null; */ export const initilisedPerformanceObserver = (infoLogger: InfoLogger): PerformanceObserver => { if (obs === null) { - infoLogger.alert(new InitalisePerformanceLoggable()); + infoLogger.info(new InitalisePerformanceLoggable()); // eslint-disable-next-line @typescript-eslint/no-unused-vars obs = new PerformanceObserver((perfObserverList, observer) => { const entries = perfObserverList.getEntries(); const loggable = new MeasureLoggable(entries); - infoLogger.alert(loggable); + infoLogger.info(loggable); }); obs.observe({ type: 'measure', buffered: true }); } From 076ff46de700c2ddf99b7aa533fd1212747b7b66 Mon Sep 17 00:00:00 2001 From: Cedric Evers <12080057+CeEv@users.noreply.github.com> Date: Mon, 24 Jun 2024 15:37:05 +0200 Subject: [PATCH 04/28] Fix console, seperate logging envirement, pass clock to log --- apps/server/src/modules/tldraw/config.ts | 2 +- apps/server/src/modules/tldraw/repo/y-mongodb.ts | 2 +- apps/server/src/modules/tldraw/tldraw-console.module.ts | 2 ++ config/default.schema.json | 6 ++++++ 4 files changed, 10 insertions(+), 2 deletions(-) diff --git a/apps/server/src/modules/tldraw/config.ts b/apps/server/src/modules/tldraw/config.ts index 1fdb3eae5e4..534ecbc06aa 100644 --- a/apps/server/src/modules/tldraw/config.ts +++ b/apps/server/src/modules/tldraw/config.ts @@ -25,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, diff --git a/apps/server/src/modules/tldraw/repo/y-mongodb.ts b/apps/server/src/modules/tldraw/repo/y-mongodb.ts index 19d1bfe5649..4c35532e662 100644 --- a/apps/server/src/modules/tldraw/repo/y-mongodb.ts +++ b/apps/server/src/modules/tldraw/repo/y-mongodb.ts @@ -122,7 +122,7 @@ export class YMongodb implements OnModuleInit { ydoc.destroy(); performance.mark('compressDocumentTransactional - end'); performance.measure( - `tldraw:YMongodb:compressDocumentTransactional::${docName}`, + `tldraw:YMongodb:compressDocumentTransactional::${docName}, clock=${clock}`, 'compressDocumentTransactional - start', 'compressDocumentTransactional - end' ); diff --git a/apps/server/src/modules/tldraw/tldraw-console.module.ts b/apps/server/src/modules/tldraw/tldraw-console.module.ts index 171505bd510..a8b957a8487 100644 --- a/apps/server/src/modules/tldraw/tldraw-console.module.ts +++ b/apps/server/src/modules/tldraw/tldraw-console.module.ts @@ -7,6 +7,7 @@ import { Dictionary, IPrimaryKey } from '@mikro-orm/core'; import { RabbitMQWrapperModule } from '@infra/rabbitmq'; import { ConsoleWriterModule } from '@infra/console'; import { ConsoleModule } from 'nestjs-console'; +import { CoreModule } from '@src/core'; import { FilesStorageClientModule } from '../files-storage-client'; import { config, TLDRAW_DB_URL } from './config'; import { TldrawDrawing } from './entities'; @@ -23,6 +24,7 @@ const defaultMikroOrmOptions: MikroOrmModuleSyncOptions = { @Module({ imports: [ + CoreModule, ConsoleModule, ConsoleWriterModule, RabbitMQWrapperModule, diff --git a/config/default.schema.json b/config/default.schema.json index d20ce638db7..9fbb393aa9a 100644 --- a/config/default.schema.json +++ b/config/default.schema.json @@ -1582,6 +1582,12 @@ "type": "boolean", "description": "Activate the performance measure for overserved areas.", "default": true + }, + "LOG_LEVEL": { + "type": "string", + "default": "info", + "description": "Nest Log level for api. The http flag is for request logging. The http flag do only work by api methods with added 'request logging interceptor'.", + "enum": ["emerg", "alert", "crit", "error", "warning", "notice", "info", "debug"] } }, "default": { From a3fb6360e1819a973eb4b69cb1bb5d7c4ce55523 Mon Sep 17 00:00:00 2001 From: Cedric Evers <12080057+CeEv@users.noreply.github.com> Date: Wed, 26 Jun 2024 16:30:43 +0200 Subject: [PATCH 05/28] improve readability of measure logs --- .../src/modules/tldraw/repo/y-mongodb.ts | 12 ++-- .../tldraw/service/tldraw.ws.service.ts | 70 ++++++++++--------- .../measure-utils/performance-observer.ts | 15 +++- 3 files changed, 58 insertions(+), 39 deletions(-) diff --git a/apps/server/src/modules/tldraw/repo/y-mongodb.ts b/apps/server/src/modules/tldraw/repo/y-mongodb.ts index 4c35532e662..68815eec6d5 100644 --- a/apps/server/src/modules/tldraw/repo/y-mongodb.ts +++ b/apps/server/src/modules/tldraw/repo/y-mongodb.ts @@ -7,7 +7,7 @@ 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 { initilisedPerformanceObserver } from '@shared/common/measure-utils'; +import { formatMessureLog, initilisedPerformanceObserver } from '@shared/common/measure-utils'; import { Logger } from '@src/core/logger'; import { TldrawConfig } from '../config'; import { WsSharedDocDo } from '../domain'; @@ -120,11 +120,13 @@ export class YMongodb implements OnModuleInit { await this.clearUpdatesRange(docName, 0, clock); ydoc.destroy(); - performance.mark('compressDocumentTransactional - end'); performance.measure( - `tldraw:YMongodb:compressDocumentTransactional::${docName}, clock=${clock}`, - 'compressDocumentTransactional - start', - 'compressDocumentTransactional - end' + formatMessureLog({ + location: 'tldraw:YMongodb:compressDocumentTransactional', + doc_name: docName, + clock, + }), + 'compressDocumentTransactional - start' ); }); } 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 0038ae7062c..703d545e4f5 100644 --- a/apps/server/src/modules/tldraw/service/tldraw.ws.service.ts +++ b/apps/server/src/modules/tldraw/service/tldraw.ws.service.ts @@ -8,7 +8,7 @@ import { Buffer } from 'node:buffer'; import { YMap } from 'yjs/dist/src/types/YMap'; import { DomainErrorHandler } from '@src/core'; import { Logger } from '@src/core/logger'; -import { initilisedPerformanceObserver } from '@shared/common/measure-utils'; +import { formatMessureLog, initilisedPerformanceObserver } from '@shared/common/measure-utils'; import { TldrawRedisService } from '../redis'; import { CloseConnectionLoggable, @@ -51,7 +51,7 @@ export class TldrawWsService implements OnModuleInit { } public async closeConnection(doc: WsSharedDocDo, ws: WebSocket): Promise { - performance.mark('closeConnection - start'); + performance.mark('closeConnection'); if (doc.connections.has(ws)) { const controlledIds = doc.connections.get(ws); doc.connections.delete(ws); @@ -62,11 +62,13 @@ export class TldrawWsService implements OnModuleInit { ws.close(); await this.finalizeIfNoConnections(doc); - performance.mark('closeConnection - end'); performance.measure( - `tldraw:TldrawWsService:closeConnection::${doc.name}`, - 'closeConnection - start', - 'closeConnection - end' + formatMessureLog({ + location: 'tldraw:TldrawWsService:closeConnection', + doc_name: doc.name, + doc_connection_total: doc.connections.size, + }), + 'closeConnection' ); } @@ -197,16 +199,10 @@ export class TldrawWsService implements OnModuleInit { public async setupWsConnection(ws: WebSocket, docName: string): Promise { ws.binaryType = 'arraybuffer'; - performance.mark('get document - start'); + performance.mark('setupWsConnection'); // get doc, initialize if it does not exist yet - update this.getDocument(docName) can be return null const doc = await this.getDocument(docName); doc.connections.set(ws, new Set()); - performance.mark('ws connection to doc - done'); - performance.measure( - `tldraw:TldrawWsService:setupWsConnection::${docName}`, - 'get document - start', - 'ws connection to doc - done' - ); ws.on('error', (err) => { this.domainErrorHandler.exec(new WebsocketErrorLoggable(err)); @@ -247,27 +243,37 @@ export class TldrawWsService implements OnModuleInit { 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( + formatMessureLog({ + location: 'tldraw:TldrawWsService:setupWsConnection', + doc_name: docName, + doc_awareness_state_total: awarenessStates.size, + doc_connection_total: doc.connections.size, + pod_doc_total: this.docs.size, + }), + 'setupWsConnection' + ); } private async finalizeIfNoConnections(doc: WsSharedDocDo) { diff --git a/apps/server/src/shared/common/measure-utils/performance-observer.ts b/apps/server/src/shared/common/measure-utils/performance-observer.ts index 270f297b73a..7a6bed69b6a 100644 --- a/apps/server/src/shared/common/measure-utils/performance-observer.ts +++ b/apps/server/src/shared/common/measure-utils/performance-observer.ts @@ -13,7 +13,12 @@ class MeasureLoggable implements Loggable { } getLogMessage(): LoggableMessage { - const data = JSON.stringify(this.entries); + const formatedStrings = this.entries.map((entry) => { + const mappedInfos = `${entry.name}, duration:${entry.duration} }`; + + return mappedInfos; + }); + const data = `[${formatedStrings.join(', ')}]`; return { message: 'Measure result', @@ -53,7 +58,7 @@ export const initilisedPerformanceObserver = (infoLogger: InfoLogger): Performan infoLogger.info(new InitalisePerformanceLoggable()); // eslint-disable-next-line @typescript-eslint/no-unused-vars obs = new PerformanceObserver((perfObserverList, observer) => { - const entries = perfObserverList.getEntries(); + const entries = perfObserverList.getEntriesByType('measure'); const loggable = new MeasureLoggable(entries); infoLogger.info(loggable); }); @@ -62,3 +67,9 @@ export const initilisedPerformanceObserver = (infoLogger: InfoLogger): Performan return obs; }; + +export const formatMessureLog = (object: Record): string => { + const jsonString = Object.entries(object).map((array) => array.join(': ')); + + return `{ ${jsonString.join(', ')} `; +}; From 1b9719a88ab5147d675961e5d4dbca21502c9f36 Mon Sep 17 00:00:00 2001 From: Cedric Evers <12080057+CeEv@users.noreply.github.com> Date: Wed, 26 Jun 2024 16:39:25 +0200 Subject: [PATCH 06/28] fix test setup --- apps/server/src/modules/tldraw/repo/y-mongodb.spec.ts | 5 +++++ .../src/modules/tldraw/service/tldraw.ws.service.spec.ts | 5 +++++ apps/server/src/modules/tldraw/service/tldraw.ws.service.ts | 3 ++- 3 files changed, 12 insertions(+), 1 deletion(-) 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..58b468bda87 100644 --- a/apps/server/src/modules/tldraw/repo/y-mongodb.spec.ts +++ b/apps/server/src/modules/tldraw/repo/y-mongodb.spec.ts @@ -7,6 +7,7 @@ import { createMock } from '@golevelup/ts-jest'; import * as Yjs from 'yjs'; import { createConfigModuleOptions } from '@src/config'; import { DomainErrorHandler } from '@src/core'; +import { Logger } from '@src/core/logger'; import { tldrawEntityFactory, tldrawTestConfig } from '../testing'; import { TldrawDrawing } from '../entities'; import { TldrawRepo } from './tldraw.repo'; @@ -40,6 +41,10 @@ describe('YMongoDb', () => { provide: DomainErrorHandler, useValue: createMock(), }, + { + provide: Logger, + useValue: createMock(), + }, ], }).compile(); 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..2c4c867ed55 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 @@ -16,6 +16,7 @@ import { ConfigModule } from '@nestjs/config'; import { createConfigModuleOptions } from '@src/config'; import { MongoMemoryDatabaseModule } from '@infra/database'; import { DomainErrorHandler } from '@src/core'; +import { Logger } from '@src/core/logger'; import { TldrawRedisFactory, TldrawRedisService } from '../redis'; import { TldrawWs } from '../controller'; import { TldrawDrawing } from '../entities'; @@ -101,6 +102,10 @@ describe('TldrawWSService', () => { provide: DomainErrorHandler, useValue: createMock(), }, + { + provide: Logger, + useValue: createMock(), + }, { provide: HttpService, useValue: createMock(), 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 703d545e4f5..6ce5a00b3e8 100644 --- a/apps/server/src/modules/tldraw/service/tldraw.ws.service.ts +++ b/apps/server/src/modules/tldraw/service/tldraw.ws.service.ts @@ -302,7 +302,7 @@ export class TldrawWsService implements OnModuleInit { this.metricsService.decrementNumberOfBoardsOnServerCounter(); } } - + /* 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 @@ -330,6 +330,7 @@ export class TldrawWsService implements OnModuleInit { return usedAssets; } + */ private sendUpdateToConnectedClients(update: Uint8Array, doc: WsSharedDocDo): void { const encoder = encoding.createEncoder(); From c7dc6fe9fc7191359bbe4fdf986e7a76e695f3f9 Mon Sep 17 00:00:00 2001 From: Cedric Evers <12080057+CeEv@users.noreply.github.com> Date: Wed, 26 Jun 2024 16:40:26 +0200 Subject: [PATCH 07/28] linter --- .../src/modules/tldraw/service/tldraw.ws.service.ts | 10 +--------- 1 file changed, 1 insertion(+), 9 deletions(-) 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 6ce5a00b3e8..a21ab193ed7 100644 --- a/apps/server/src/modules/tldraw/service/tldraw.ws.service.ts +++ b/apps/server/src/modules/tldraw/service/tldraw.ws.service.ts @@ -5,7 +5,6 @@ import { encodeAwarenessUpdate, removeAwarenessStates } from 'y-protocols/awaren 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 { Logger } from '@src/core/logger'; import { formatMessureLog, initilisedPerformanceObserver } from '@shared/common/measure-utils'; @@ -17,14 +16,7 @@ import { WsSharedDocErrorLoggable, } from '../loggable'; import { TldrawConfig } from '../config'; -import { - AwarenessConnectionsUpdate, - TldrawAsset, - TldrawShape, - UpdateOrigin, - UpdateType, - WSMessageType, -} from '../types'; +import { AwarenessConnectionsUpdate, UpdateOrigin, UpdateType, WSMessageType } from '../types'; import { WsSharedDocDo } from '../domain'; import { TldrawBoardRepo } from '../repo'; import { MetricsService } from '../metrics'; From 30b944ce7e95c28e6ffc5fcebbea7bcc493eb530 Mon Sep 17 00:00:00 2001 From: Cedric Evers <12080057+CeEv@users.noreply.github.com> Date: Wed, 26 Jun 2024 17:00:58 +0200 Subject: [PATCH 08/28] rename tldrawEntity const to avoid misunderstanding with ydoc --- .../src/modules/tldraw/repo/y-mongodb.ts | 36 ++++++++++--------- 1 file changed, 20 insertions(+), 16 deletions(-) diff --git a/apps/server/src/modules/tldraw/repo/y-mongodb.ts b/apps/server/src/modules/tldraw/repo/y-mongodb.ts index 68815eec6d5..46e7d407978 100644 --- a/apps/server/src/modules/tldraw/repo/y-mongodb.ts +++ b/apps/server/src/modules/tldraw/repo/y-mongodb.ts @@ -103,7 +103,7 @@ export class YMongodb implements OnModuleInit { // return value is not void, need to be changed public compressDocumentTransactional(docName: string): Promise { - performance.mark('compressDocumentTransactional - start'); + performance.mark('compressDocumentTransactional'); return this._transact(docName, async () => { const updates = await this.getMongoUpdates(docName); @@ -126,7 +126,7 @@ export class YMongodb implements OnModuleInit { doc_name: docName, clock, }), - 'compressDocumentTransactional - start' + 'compressDocumentTransactional' ); }); } @@ -162,13 +162,17 @@ export class YMongodb implements OnModuleInit { 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 part = tldrawDrawingEntities[i]; + + if (!this.isSameClock(part, tldrawDrawingEntity)) { break; } @@ -184,12 +188,12 @@ export class YMongodb implements OnModuleInit { /** * 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 doc = tldrawDrawingEntities[i]; if (!doc.part) { updates.push(Buffer.from(doc.value.buffer)); @@ -197,7 +201,7 @@ export class YMongodb implements OnModuleInit { if (doc.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(doc, tldrawDrawingEntities, i); updates.push(Buffer.concat(parts)); } } @@ -209,9 +213,9 @@ export class YMongodb implements OnModuleInit { */ private async getMongoUpdates(docName: string, opts = {}): Promise { const uniqueKey = KeyFactory.createForUpdate(docName); - const docs = await this.getMongoBulkData(uniqueKey, opts); + const tldrawDrawingEntitiess = await this.getMongoBulkData(uniqueKey, opts); - return this.convertMongoUpdates(docs); + return this.convertMongoUpdates(tldrawDrawingEntities); } private async writeStateVector(docName: string, sv: Uint8Array, clock: number): Promise { From c28115bbd359df14d19e8f9f8a089ec749d1db98 Mon Sep 17 00:00:00 2001 From: Cedric Evers <12080057+CeEv@users.noreply.github.com> Date: Wed, 26 Jun 2024 17:09:29 +0200 Subject: [PATCH 09/28] fix typo --- apps/server/src/modules/tldraw/repo/y-mongodb.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/apps/server/src/modules/tldraw/repo/y-mongodb.ts b/apps/server/src/modules/tldraw/repo/y-mongodb.ts index 46e7d407978..b7fedc006b5 100644 --- a/apps/server/src/modules/tldraw/repo/y-mongodb.ts +++ b/apps/server/src/modules/tldraw/repo/y-mongodb.ts @@ -213,7 +213,7 @@ export class YMongodb implements OnModuleInit { */ private async getMongoUpdates(docName: string, opts = {}): Promise { const uniqueKey = KeyFactory.createForUpdate(docName); - const tldrawDrawingEntitiess = await this.getMongoBulkData(uniqueKey, opts); + const tldrawDrawingEntities = await this.getMongoBulkData(uniqueKey, opts); return this.convertMongoUpdates(tldrawDrawingEntities); } From c08170434cf48f702a338805f07b032b34d978e2 Mon Sep 17 00:00:00 2001 From: Cedric Evers <12080057+CeEv@users.noreply.github.com> Date: Wed, 26 Jun 2024 17:15:08 +0200 Subject: [PATCH 10/28] renames --- .../server/src/modules/tldraw/repo/y-mongodb.ts | 17 ++++++++++------- 1 file changed, 10 insertions(+), 7 deletions(-) diff --git a/apps/server/src/modules/tldraw/repo/y-mongodb.ts b/apps/server/src/modules/tldraw/repo/y-mongodb.ts index b7fedc006b5..50c5cecc5a3 100644 --- a/apps/server/src/modules/tldraw/repo/y-mongodb.ts +++ b/apps/server/src/modules/tldraw/repo/y-mongodb.ts @@ -270,20 +270,23 @@ export class YMongodb implements OnModuleInit { 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; } } From ca3772243bfa7f01f3cfe08f4c178c72cc4f74ad Mon Sep 17 00:00:00 2001 From: Cedric Evers <12080057+CeEv@users.noreply.github.com> Date: Wed, 26 Jun 2024 17:17:48 +0200 Subject: [PATCH 11/28] rename --- .../src/modules/tldraw/repo/y-mongodb.ts | 20 +++++++++---------- 1 file changed, 10 insertions(+), 10 deletions(-) diff --git a/apps/server/src/modules/tldraw/repo/y-mongodb.ts b/apps/server/src/modules/tldraw/repo/y-mongodb.ts index 50c5cecc5a3..b3a1a5ad285 100644 --- a/apps/server/src/modules/tldraw/repo/y-mongodb.ts +++ b/apps/server/src/modules/tldraw/repo/y-mongodb.ts @@ -170,16 +170,16 @@ export class YMongodb implements OnModuleInit { const parts = [Buffer.from(tldrawDrawingEntity.value.buffer)]; let currentPartId: number | undefined = tldrawDrawingEntity.part; for (let i = docIndex + 1; i < tldrawDrawingEntities.length; i += 1) { - const part = tldrawDrawingEntities[i]; + const entity = tldrawDrawingEntities[i]; - if (!this.isSameClock(part, tldrawDrawingEntity)) { + 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; @@ -193,15 +193,15 @@ export class YMongodb implements OnModuleInit { const updates: Buffer[] = []; for (let i = 0; i < tldrawDrawingEntities.length; i += 1) { - const doc = tldrawDrawingEntities[i]; + 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, tldrawDrawingEntities, i); + const parts = this.mergeDocsTogether(tldrawDrawingEntity, tldrawDrawingEntities, i); updates.push(Buffer.concat(parts)); } } From 2e85f104ac07db34345542215a51f3d9447974d1 Mon Sep 17 00:00:00 2001 From: Cedric Evers <12080057+CeEv@users.noreply.github.com> Date: Wed, 26 Jun 2024 17:28:42 +0200 Subject: [PATCH 12/28] push additional metric --- apps/server/src/modules/tldraw/repo/y-mongodb.ts | 14 +++++++++++++- 1 file changed, 13 insertions(+), 1 deletion(-) diff --git a/apps/server/src/modules/tldraw/repo/y-mongodb.ts b/apps/server/src/modules/tldraw/repo/y-mongodb.ts index b3a1a5ad285..b82ab91917a 100644 --- a/apps/server/src/modules/tldraw/repo/y-mongodb.ts +++ b/apps/server/src/modules/tldraw/repo/y-mongodb.ts @@ -212,10 +212,22 @@ export class YMongodb implements OnModuleInit { * Get all document updates for a specific document. */ private async getMongoUpdates(docName: string, opts = {}): Promise { + performance.mark('getMongoUpdates'); const uniqueKey = KeyFactory.createForUpdate(docName); const tldrawDrawingEntities = await this.getMongoBulkData(uniqueKey, opts); - return this.convertMongoUpdates(tldrawDrawingEntities); + const buffer = this.convertMongoUpdates(tldrawDrawingEntities); + + performance.measure( + formatMessureLog({ + location: 'tldraw:YMongodb:getMongoUpdates', + doc_name: docName, + loaded_tldraw_entities_total: tldrawDrawingEntities.length, + }), + 'getMongoUpdates' + ); + + return buffer; } private async writeStateVector(docName: string, sv: Uint8Array, clock: number): Promise { From 04fa39470026f53c03af288eec035adf9c60743b Mon Sep 17 00:00:00 2001 From: Cedric Evers <12080057+CeEv@users.noreply.github.com> Date: Thu, 27 Jun 2024 14:24:46 +0200 Subject: [PATCH 13/28] Fix descriptions. --- config/default.schema.json | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/config/default.schema.json b/config/default.schema.json index 9fbb393aa9a..de4f3024eb8 100644 --- a/config/default.schema.json +++ b/config/default.schema.json @@ -1580,13 +1580,13 @@ }, "PERFORMANCE_MEASURE_ENABLED": { "type": "boolean", - "description": "Activate the performance measure for overserved areas.", + "description": "Activate the performance measure for observed areas.", "default": true }, "LOG_LEVEL": { "type": "string", "default": "info", - "description": "Nest Log level for api. The http flag is for request logging. The http flag do only work by api methods with added 'request logging interceptor'.", + "description": "Define log level for tldraw.", "enum": ["emerg", "alert", "crit", "error", "warning", "notice", "info", "debug"] } }, From b7129332630b692eeadfefea2d25751ff3de8acb Mon Sep 17 00:00:00 2001 From: dyedwiper Date: Thu, 27 Jun 2024 16:21:26 +0200 Subject: [PATCH 14/28] Restructure logging --- .../src/modules/tldraw/repo/y-mongodb.ts | 30 +++++-------- .../tldraw/service/tldraw.ws.service.ts | 45 +++++++++---------- .../measure-utils/performance-observer.ts | 34 +++++--------- 3 files changed, 43 insertions(+), 66 deletions(-) diff --git a/apps/server/src/modules/tldraw/repo/y-mongodb.ts b/apps/server/src/modules/tldraw/repo/y-mongodb.ts index b82ab91917a..b4e6802b25d 100644 --- a/apps/server/src/modules/tldraw/repo/y-mongodb.ts +++ b/apps/server/src/modules/tldraw/repo/y-mongodb.ts @@ -1,14 +1,14 @@ import { BulkWriteResult } from '@mikro-orm/mongodb/node_modules/mongodb'; import { Injectable, OnModuleInit } from '@nestjs/common'; import { ConfigService } from '@nestjs/config'; +import { initilisedPerformanceObserver } from '@shared/common/measure-utils'; +import { DomainErrorHandler } from '@src/core'; +import { Logger } from '@src/core/logger'; 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 { formatMessureLog, initilisedPerformanceObserver } from '@shared/common/measure-utils'; -import { Logger } from '@src/core/logger'; import { TldrawConfig } from '../config'; import { WsSharedDocDo } from '../domain'; import { TldrawDrawing } from '../entities'; @@ -120,14 +120,10 @@ export class YMongodb implements OnModuleInit { await this.clearUpdatesRange(docName, 0, clock); ydoc.destroy(); - performance.measure( - formatMessureLog({ - location: 'tldraw:YMongodb:compressDocumentTransactional', - doc_name: docName, - clock, - }), - 'compressDocumentTransactional' - ); + performance.measure('tldraw:YMongodb:compressDocumentTransactional', { + start: 'compressDocumentTransactional', + detail: { doc_name: docName, clock }, + }); }); } @@ -218,14 +214,10 @@ export class YMongodb implements OnModuleInit { const buffer = this.convertMongoUpdates(tldrawDrawingEntities); - performance.measure( - formatMessureLog({ - location: 'tldraw:YMongodb:getMongoUpdates', - doc_name: docName, - loaded_tldraw_entities_total: tldrawDrawingEntities.length, - }), - 'getMongoUpdates' - ); + performance.measure('tldraw:YMongodb:getMongoUpdates', { + start: 'getMongoUpdates', + detail: { doc_name: docName, loaded_tldraw_entities_total: tldrawDrawingEntities.length }, + }); return buffer; } 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 a21ab193ed7..4d95a8e6849 100644 --- a/apps/server/src/modules/tldraw/service/tldraw.ws.service.ts +++ b/apps/server/src/modules/tldraw/service/tldraw.ws.service.ts @@ -1,25 +1,25 @@ import { Injectable, NotAcceptableException, OnModuleInit } from '@nestjs/common'; import { ConfigService } from '@nestjs/config'; +import { initilisedPerformanceObserver } from '@shared/common/measure-utils'; +import { DomainErrorHandler } from '@src/core'; +import { Logger } from '@src/core/logger'; +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 { DomainErrorHandler } from '@src/core'; -import { Logger } from '@src/core/logger'; -import { formatMessureLog, initilisedPerformanceObserver } from '@shared/common/measure-utils'; -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, 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 implements OnModuleInit { @@ -54,14 +54,10 @@ export class TldrawWsService implements OnModuleInit { ws.close(); await this.finalizeIfNoConnections(doc); - performance.measure( - formatMessureLog({ - location: 'tldraw:TldrawWsService:closeConnection', - doc_name: doc.name, - doc_connection_total: doc.connections.size, - }), - 'closeConnection' - ); + performance.measure('tldraw:TldrawWsService:closeConnection', { + detail: { doc_name: doc.name, doc_connection_total: doc.connections.size }, + start: 'closeConnection', + }); } public send(doc: WsSharedDocDo, ws: WebSocket, message: Uint8Array): void { @@ -256,16 +252,15 @@ export class TldrawWsService implements OnModuleInit { this.metricsService.incrementNumberOfUsersOnServerCounter(); - performance.measure( - formatMessureLog({ - location: 'tldraw:TldrawWsService:setupWsConnection', - doc_name: docName, + performance.measure('tldraw:TldrawWsService:setupWsConnection', { + detail: { + doc_name: doc.name, doc_awareness_state_total: awarenessStates.size, doc_connection_total: doc.connections.size, pod_doc_total: this.docs.size, - }), - 'setupWsConnection' - ); + }, + start: 'setupWsConnection', + }); } private async finalizeIfNoConnections(doc: WsSharedDocDo) { diff --git a/apps/server/src/shared/common/measure-utils/performance-observer.ts b/apps/server/src/shared/common/measure-utils/performance-observer.ts index 7a6bed69b6a..13207dadb76 100644 --- a/apps/server/src/shared/common/measure-utils/performance-observer.ts +++ b/apps/server/src/shared/common/measure-utils/performance-observer.ts @@ -1,4 +1,5 @@ -import { PerformanceObserver, PerformanceEntry } from 'node:perf_hooks'; +import { PerformanceEntry, PerformanceObserver } from 'node:perf_hooks'; +import util from 'util'; import { Loggable, LoggableMessage } from '../loggable'; interface InfoLogger { @@ -6,24 +7,18 @@ interface InfoLogger { } class MeasureLoggable implements Loggable { - entries: PerformanceEntry[] = []; - - constructor(entries: PerformanceEntry[]) { - this.entries = entries; - } + constructor(private readonly entry: PerformanceEntry) {} getLogMessage(): LoggableMessage { - const formatedStrings = this.entries.map((entry) => { - const mappedInfos = `${entry.name}, duration:${entry.duration} }`; + const detail = util.inspect(this.entry.detail).replace(/\n/g, '').replace(/\\n/g, ''); + const data = `location: ${this.entry.name}, duration: ${this.entry.duration}, detail: ${detail}`; - return mappedInfos; - }); - const data = `[${formatedStrings.join(', ')}]`; - - return { - message: 'Measure result', + const message = { + message: `Performance measure result`, data, }; + + return message; } } @@ -59,17 +54,12 @@ export const initilisedPerformanceObserver = (infoLogger: InfoLogger): Performan // eslint-disable-next-line @typescript-eslint/no-unused-vars obs = new PerformanceObserver((perfObserverList, observer) => { const entries = perfObserverList.getEntriesByType('measure'); - const loggable = new MeasureLoggable(entries); - infoLogger.info(loggable); + entries.forEach((entry) => { + infoLogger.info(new MeasureLoggable(entry)); + }); }); obs.observe({ type: 'measure', buffered: true }); } return obs; }; - -export const formatMessureLog = (object: Record): string => { - const jsonString = Object.entries(object).map((array) => array.join(': ')); - - return `{ ${jsonString.join(', ')} `; -}; From fb992fd4b8feb274172ae5e0fef0f4cac4a11aa4 Mon Sep 17 00:00:00 2001 From: dyedwiper Date: Fri, 28 Jun 2024 11:03:57 +0200 Subject: [PATCH 15/28] Restructure init of perf observer --- .../src/modules/tldraw/repo/y-mongodb.ts | 13 ++---- .../tldraw/service/tldraw.ws.service.ts | 19 +++----- .../modules/tldraw/tldraw-console.module.ts | 30 ++++++++----- .../src/modules/tldraw/tldraw-ws.module.ts | 26 +++++++---- .../measure-utils/performance-observer.ts | 43 ++++--------------- 5 files changed, 56 insertions(+), 75 deletions(-) diff --git a/apps/server/src/modules/tldraw/repo/y-mongodb.ts b/apps/server/src/modules/tldraw/repo/y-mongodb.ts index b4e6802b25d..b486449f911 100644 --- a/apps/server/src/modules/tldraw/repo/y-mongodb.ts +++ b/apps/server/src/modules/tldraw/repo/y-mongodb.ts @@ -1,7 +1,6 @@ import { BulkWriteResult } from '@mikro-orm/mongodb/node_modules/mongodb'; -import { Injectable, OnModuleInit } from '@nestjs/common'; +import { Injectable } from '@nestjs/common'; import { ConfigService } from '@nestjs/config'; -import { initilisedPerformanceObserver } from '@shared/common/measure-utils'; import { DomainErrorHandler } from '@src/core'; import { Logger } from '@src/core/logger'; import { Buffer } from 'buffer'; @@ -18,7 +17,7 @@ import { KeyFactory, Version } from './key.factory'; import { TldrawRepo } from './tldraw.repo'; @Injectable() -export class YMongodb implements OnModuleInit { +export class YMongodb { private readonly _transact: >(docName: string, fn: () => T) => T; // scope the queue of the transaction to each docName @@ -65,12 +64,6 @@ export class YMongodb implements OnModuleInit { }; } - onModuleInit() { - if (this.configService.get('PERFORMANCE_MEASURE_ENABLED') === true) { - initilisedPerformanceObserver(this.logger); - } - } - public async createIndex(): Promise { await this.repo.ensureIndexes(); } @@ -120,6 +113,7 @@ export class YMongodb implements OnModuleInit { await this.clearUpdatesRange(docName, 0, clock); ydoc.destroy(); + performance.measure('tldraw:YMongodb:compressDocumentTransactional', { start: 'compressDocumentTransactional', detail: { doc_name: docName, clock }, @@ -209,6 +203,7 @@ export class YMongodb implements OnModuleInit { */ private async getMongoUpdates(docName: string, opts = {}): Promise { performance.mark('getMongoUpdates'); + const uniqueKey = KeyFactory.createForUpdate(docName); const tldrawDrawingEntities = await this.getMongoBulkData(uniqueKey, opts); 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 4d95a8e6849..343be4b2f68 100644 --- a/apps/server/src/modules/tldraw/service/tldraw.ws.service.ts +++ b/apps/server/src/modules/tldraw/service/tldraw.ws.service.ts @@ -1,6 +1,5 @@ -import { Injectable, NotAcceptableException, OnModuleInit } from '@nestjs/common'; +import { Injectable, NotAcceptableException } from '@nestjs/common'; import { ConfigService } from '@nestjs/config'; -import { initilisedPerformanceObserver } from '@shared/common/measure-utils'; import { DomainErrorHandler } from '@src/core'; import { Logger } from '@src/core/logger'; import { decoding, encoding } from 'lib0'; @@ -22,7 +21,7 @@ import { TldrawBoardRepo } from '../repo'; import { AwarenessConnectionsUpdate, UpdateOrigin, UpdateType, WSMessageType } from '../types'; @Injectable() -export class TldrawWsService implements OnModuleInit { +export class TldrawWsService { public docs = new Map(); constructor( @@ -36,12 +35,6 @@ export class TldrawWsService implements OnModuleInit { this.tldrawRedisService.sub.on('messageBuffer', (channel, message) => this.redisMessageHandler(channel, message)); } - onModuleInit() { - if (this.configService.get('PERFORMANCE_MEASURE_ENABLED') === true) { - initilisedPerformanceObserver(this.logger); - } - } - public async closeConnection(doc: WsSharedDocDo, ws: WebSocket): Promise { performance.mark('closeConnection'); if (doc.connections.has(ws)) { @@ -54,9 +47,10 @@ export class TldrawWsService implements OnModuleInit { ws.close(); await this.finalizeIfNoConnections(doc); + performance.measure('tldraw:TldrawWsService:closeConnection', { - detail: { doc_name: doc.name, doc_connection_total: doc.connections.size }, start: 'closeConnection', + detail: { doc_name: doc.name, doc_connection_total: doc.connections.size }, }); } @@ -185,9 +179,10 @@ export class TldrawWsService implements OnModuleInit { }; public async setupWsConnection(ws: WebSocket, docName: string): Promise { + performance.mark('setupWsConnection'); + ws.binaryType = 'arraybuffer'; - performance.mark('setupWsConnection'); // get doc, initialize if it does not exist yet - update this.getDocument(docName) can be return null const doc = await this.getDocument(docName); doc.connections.set(ws, new Set()); @@ -253,13 +248,13 @@ export class TldrawWsService implements OnModuleInit { 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_doc_total: this.docs.size, }, - start: 'setupWsConnection', }); } diff --git a/apps/server/src/modules/tldraw/tldraw-console.module.ts b/apps/server/src/modules/tldraw/tldraw-console.module.ts index a8b957a8487..c40b35eef7d 100644 --- a/apps/server/src/modules/tldraw/tldraw-console.module.ts +++ b/apps/server/src/modules/tldraw/tldraw-console.module.ts @@ -1,19 +1,20 @@ +import { ConsoleWriterModule } from '@infra/console'; +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 { ConfigModule, ConfigService } from '@nestjs/config'; +import { initilisedPerformanceObserver } from '@shared/common/measure-utils'; import { createConfigModuleOptions, DB_PASSWORD, DB_USERNAME } from '@src/config'; -import { LoggerModule } from '@src/core/logger'; -import { MikroOrmModule, MikroOrmModuleSyncOptions } from '@mikro-orm/nestjs'; -import { Dictionary, IPrimaryKey } from '@mikro-orm/core'; -import { RabbitMQWrapperModule } from '@infra/rabbitmq'; -import { ConsoleWriterModule } from '@infra/console'; -import { ConsoleModule } from 'nestjs-console'; import { CoreModule } from '@src/core'; +import { Logger, LoggerModule } from '@src/core/logger'; +import { ConsoleModule } from 'nestjs-console'; import { FilesStorageClientModule } from '../files-storage-client'; -import { config, TLDRAW_DB_URL } from './config'; +import { config, TldrawConfig, TLDRAW_DB_URL } from './config'; import { TldrawDrawing } from './entities'; -import { TldrawFilesStorageAdapterService } from './service'; -import { TldrawRepo, YMongodb } from './repo'; import { TldrawFilesConsole } from './job'; +import { TldrawRepo, YMongodb } from './repo'; +import { TldrawFilesStorageAdapterService } from './service'; import { TldrawDeleteFilesUc } from './uc'; const defaultMikroOrmOptions: MikroOrmModuleSyncOptions = { @@ -42,4 +43,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'); + initilisedPerformanceObserver(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..5a381108891 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 { initilisedPerformanceObserver } 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'); + initilisedPerformanceObserver(this.logger); + } + } +} diff --git a/apps/server/src/shared/common/measure-utils/performance-observer.ts b/apps/server/src/shared/common/measure-utils/performance-observer.ts index 13207dadb76..089fd9e2a2b 100644 --- a/apps/server/src/shared/common/measure-utils/performance-observer.ts +++ b/apps/server/src/shared/common/measure-utils/performance-observer.ts @@ -12,11 +12,7 @@ class MeasureLoggable implements Loggable { getLogMessage(): LoggableMessage { const detail = util.inspect(this.entry.detail).replace(/\n/g, '').replace(/\\n/g, ''); const data = `location: ${this.entry.name}, duration: ${this.entry.duration}, detail: ${detail}`; - - const message = { - message: `Performance measure result`, - data, - }; + const message = { message: `Measure result`, data }; return message; } @@ -30,36 +26,15 @@ class InitalisePerformanceLoggable implements Loggable { } } -let obs: PerformanceObserver | null = null; +export const initilisedPerformanceObserver = (infoLogger: InfoLogger): void => { + infoLogger.info(new InitalisePerformanceLoggable()); -/** - * Please note after adding the observer is avaible on the complet node process. - * This can be add in constructor of a class, in best case with feature flag. To add it or not. - * After it the messaure can be used with: - * performance.mark to create pointer and performance.messure to generate a delta between marks - * - * performance.mark('compressDocumentTransactional - start'); - * // code to messure - * performance.mark('compressDocumentTransactional - end'); - * - * performance.measure( - * `tldraw:YMongodb:compressDocumentTransactional::${docName}`, - * 'compressDocumentTransactional - start', - * 'compressDocumentTransactional - end' - * ); - */ -export const initilisedPerformanceObserver = (infoLogger: InfoLogger): PerformanceObserver => { - if (obs === null) { - infoLogger.info(new InitalisePerformanceLoggable()); - // eslint-disable-next-line @typescript-eslint/no-unused-vars - obs = new PerformanceObserver((perfObserverList, observer) => { - const entries = perfObserverList.getEntriesByType('measure'); - entries.forEach((entry) => { - infoLogger.info(new MeasureLoggable(entry)); - }); + const obs = new PerformanceObserver((perfObserverList) => { + const entries = perfObserverList.getEntriesByType('measure'); + entries.forEach((entry) => { + infoLogger.info(new MeasureLoggable(entry)); }); - obs.observe({ type: 'measure', buffered: true }); - } + }); - return obs; + obs.observe({ type: 'measure', buffered: true }); }; From 226e50ac4f2ed3b791a967fc7a396d387fbdf8a2 Mon Sep 17 00:00:00 2001 From: dyedwiper Date: Fri, 28 Jun 2024 11:06:28 +0200 Subject: [PATCH 16/28] Fix typos --- apps/server/src/modules/tldraw/tldraw-console.module.ts | 4 ++-- apps/server/src/modules/tldraw/tldraw-ws.module.ts | 4 ++-- .../src/shared/common/measure-utils/performance-observer.ts | 6 +++--- 3 files changed, 7 insertions(+), 7 deletions(-) diff --git a/apps/server/src/modules/tldraw/tldraw-console.module.ts b/apps/server/src/modules/tldraw/tldraw-console.module.ts index c40b35eef7d..9ade5880a72 100644 --- a/apps/server/src/modules/tldraw/tldraw-console.module.ts +++ b/apps/server/src/modules/tldraw/tldraw-console.module.ts @@ -4,7 +4,7 @@ import { Dictionary, IPrimaryKey } from '@mikro-orm/core'; import { MikroOrmModule, MikroOrmModuleSyncOptions } from '@mikro-orm/nestjs'; import { Module, NotFoundException } from '@nestjs/common'; import { ConfigModule, ConfigService } from '@nestjs/config'; -import { initilisedPerformanceObserver } from '@shared/common/measure-utils'; +import { initialisePerformanceObserver } from '@shared/common/measure-utils'; import { createConfigModuleOptions, DB_PASSWORD, DB_USERNAME } from '@src/config'; import { CoreModule } from '@src/core'; import { Logger, LoggerModule } from '@src/core/logger'; @@ -47,7 +47,7 @@ export class TldrawConsoleModule { constructor(private readonly logger: Logger, private readonly configService: ConfigService) { if (this.configService.get('PERFORMANCE_MEASURE_ENABLED') === true) { this.logger.setContext('PerformanceObserver'); - initilisedPerformanceObserver(this.logger); + 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 5a381108891..a4d7ba2ede6 100644 --- a/apps/server/src/modules/tldraw/tldraw-ws.module.ts +++ b/apps/server/src/modules/tldraw/tldraw-ws.module.ts @@ -3,7 +3,7 @@ import { MikroOrmModule, MikroOrmModuleSyncOptions } from '@mikro-orm/nestjs'; import { HttpModule } from '@nestjs/axios'; import { Module, NotFoundException } from '@nestjs/common'; import { ConfigModule, ConfigService } from '@nestjs/config'; -import { initilisedPerformanceObserver } from '@shared/common/measure-utils'; +import { initialisePerformanceObserver } from '@shared/common/measure-utils'; import { createConfigModuleOptions, DB_PASSWORD, DB_USERNAME } from '@src/config'; import { CoreModule } from '@src/core'; import { Logger, LoggerModule } from '@src/core/logger'; @@ -50,7 +50,7 @@ export class TldrawWsModule { constructor(private readonly logger: Logger, private readonly configService: ConfigService) { if (this.configService.get('PERFORMANCE_MEASURE_ENABLED') === true) { this.logger.setContext('PerformanceObserver'); - initilisedPerformanceObserver(this.logger); + initialisePerformanceObserver(this.logger); } } } diff --git a/apps/server/src/shared/common/measure-utils/performance-observer.ts b/apps/server/src/shared/common/measure-utils/performance-observer.ts index 089fd9e2a2b..ece6e09adc9 100644 --- a/apps/server/src/shared/common/measure-utils/performance-observer.ts +++ b/apps/server/src/shared/common/measure-utils/performance-observer.ts @@ -18,7 +18,7 @@ class MeasureLoggable implements Loggable { } } -class InitalisePerformanceLoggable implements Loggable { +class InitialisePerformanceObserverLoggable implements Loggable { getLogMessage(): LoggableMessage { return { message: 'Initialise PerformanceObserver...', @@ -26,8 +26,8 @@ class InitalisePerformanceLoggable implements Loggable { } } -export const initilisedPerformanceObserver = (infoLogger: InfoLogger): void => { - infoLogger.info(new InitalisePerformanceLoggable()); +export const initialisePerformanceObserver = (infoLogger: InfoLogger): void => { + infoLogger.info(new InitialisePerformanceObserverLoggable()); const obs = new PerformanceObserver((perfObserverList) => { const entries = perfObserverList.getEntriesByType('measure'); From 737541d376005fb5bcd814a10aa16d7316ef5a26 Mon Sep 17 00:00:00 2001 From: dyedwiper Date: Fri, 28 Jun 2024 11:11:38 +0200 Subject: [PATCH 17/28] Remove unused loggers --- .../src/modules/tldraw/repo/y-mongodb.spec.ts | 17 +++----- .../src/modules/tldraw/repo/y-mongodb.ts | 4 +- .../tldraw/service/tldraw.ws.service.spec.ts | 39 ++++++++----------- .../tldraw/service/tldraw.ws.service.ts | 4 +- 4 files changed, 25 insertions(+), 39 deletions(-) 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 58b468bda87..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,18 +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 { Logger } from '@src/core/logger'; -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 = { @@ -41,10 +40,6 @@ describe('YMongoDb', () => { provide: DomainErrorHandler, useValue: createMock(), }, - { - provide: Logger, - useValue: createMock(), - }, ], }).compile(); diff --git a/apps/server/src/modules/tldraw/repo/y-mongodb.ts b/apps/server/src/modules/tldraw/repo/y-mongodb.ts index b486449f911..edc7fae12fc 100644 --- a/apps/server/src/modules/tldraw/repo/y-mongodb.ts +++ b/apps/server/src/modules/tldraw/repo/y-mongodb.ts @@ -2,7 +2,6 @@ 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 { Logger } from '@src/core/logger'; import { Buffer } from 'buffer'; import * as binary from 'lib0/binary'; import * as encoding from 'lib0/encoding'; @@ -27,8 +26,7 @@ export class YMongodb { constructor( private readonly configService: ConfigService, private readonly repo: TldrawRepo, - private readonly domainErrorHandler: DomainErrorHandler, - private readonly logger: Logger + private readonly domainErrorHandler: DomainErrorHandler ) { // execute a transaction on a database // this will ensure that other processes are currently not writing 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 2c4c867ed55..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,30 +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 { Logger } from '@src/core/logger'; -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 = { @@ -102,10 +101,6 @@ describe('TldrawWSService', () => { provide: DomainErrorHandler, useValue: createMock(), }, - { - provide: Logger, - useValue: createMock(), - }, { provide: HttpService, useValue: createMock(), 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 343be4b2f68..ae1f26ef27a 100644 --- a/apps/server/src/modules/tldraw/service/tldraw.ws.service.ts +++ b/apps/server/src/modules/tldraw/service/tldraw.ws.service.ts @@ -1,7 +1,6 @@ import { Injectable, NotAcceptableException } from '@nestjs/common'; import { ConfigService } from '@nestjs/config'; import { DomainErrorHandler } from '@src/core'; -import { Logger } from '@src/core/logger'; import { decoding, encoding } from 'lib0'; import { Buffer } from 'node:buffer'; import WebSocket from 'ws'; @@ -29,8 +28,7 @@ export class TldrawWsService { private readonly tldrawBoardRepo: TldrawBoardRepo, private readonly domainErrorHandler: DomainErrorHandler, private readonly metricsService: MetricsService, - private readonly tldrawRedisService: TldrawRedisService, - private readonly logger: Logger + private readonly tldrawRedisService: TldrawRedisService ) { this.tldrawRedisService.sub.on('messageBuffer', (channel, message) => this.redisMessageHandler(channel, message)); } From f1ad28dffe4f501ace2beb0a8de0a41cb05b5301 Mon Sep 17 00:00:00 2001 From: dyedwiper Date: Fri, 28 Jun 2024 11:13:02 +0200 Subject: [PATCH 18/28] Update logger context --- apps/server/src/modules/tldraw/tldraw-console.module.ts | 2 +- apps/server/src/modules/tldraw/tldraw-ws.module.ts | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/apps/server/src/modules/tldraw/tldraw-console.module.ts b/apps/server/src/modules/tldraw/tldraw-console.module.ts index 9ade5880a72..5b6cd4e56b1 100644 --- a/apps/server/src/modules/tldraw/tldraw-console.module.ts +++ b/apps/server/src/modules/tldraw/tldraw-console.module.ts @@ -46,7 +46,7 @@ const defaultMikroOrmOptions: MikroOrmModuleSyncOptions = { export class TldrawConsoleModule { constructor(private readonly logger: Logger, private readonly configService: ConfigService) { if (this.configService.get('PERFORMANCE_MEASURE_ENABLED') === true) { - this.logger.setContext('PerformanceObserver'); + this.logger.setContext('PerformanceObserver:TldrawConsoleModule'); 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 a4d7ba2ede6..f11a9992df9 100644 --- a/apps/server/src/modules/tldraw/tldraw-ws.module.ts +++ b/apps/server/src/modules/tldraw/tldraw-ws.module.ts @@ -49,7 +49,7 @@ const defaultMikroOrmOptions: MikroOrmModuleSyncOptions = { export class TldrawWsModule { constructor(private readonly logger: Logger, private readonly configService: ConfigService) { if (this.configService.get('PERFORMANCE_MEASURE_ENABLED') === true) { - this.logger.setContext('PerformanceObserver'); + this.logger.setContext('PerformanceObserver:TldrawWsModule'); initialisePerformanceObserver(this.logger); } } From efc6868375ef093b2d417481e99bbac43dd77ef6 Mon Sep 17 00:00:00 2001 From: dyedwiper Date: Fri, 28 Jun 2024 11:14:31 +0200 Subject: [PATCH 19/28] Remove unused method --- .../tldraw/service/tldraw.ws.service.ts | 29 ------------------- 1 file changed, 29 deletions(-) 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 ae1f26ef27a..e97e32f5332 100644 --- a/apps/server/src/modules/tldraw/service/tldraw.ws.service.ts +++ b/apps/server/src/modules/tldraw/service/tldraw.ws.service.ts @@ -282,35 +282,6 @@ export class TldrawWsService { this.metricsService.decrementNumberOfBoardsOnServerCounter(); } } - /* - 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(); From a6641ae96152eafbec70384476565d9c9849734a Mon Sep 17 00:00:00 2001 From: dyedwiper Date: Mon, 1 Jul 2024 11:54:29 +0200 Subject: [PATCH 20/28] Cluster entries in logs --- .../measure-utils/performance-observer.ts | 17 +++++++++-------- 1 file changed, 9 insertions(+), 8 deletions(-) diff --git a/apps/server/src/shared/common/measure-utils/performance-observer.ts b/apps/server/src/shared/common/measure-utils/performance-observer.ts index ece6e09adc9..92ea4c98520 100644 --- a/apps/server/src/shared/common/measure-utils/performance-observer.ts +++ b/apps/server/src/shared/common/measure-utils/performance-observer.ts @@ -6,13 +6,16 @@ interface InfoLogger { info(input: Loggable): void; } -class MeasureLoggable implements Loggable { - constructor(private readonly entry: PerformanceEntry) {} +class MeasuresLoggable implements Loggable { + constructor(private readonly entries: PerformanceEntry[]) {} getLogMessage(): LoggableMessage { - const detail = util.inspect(this.entry.detail).replace(/\n/g, '').replace(/\\n/g, ''); - const data = `location: ${this.entry.name}, duration: ${this.entry.duration}, detail: ${detail}`; - const message = { message: `Measure result`, data }; + 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; } @@ -31,9 +34,7 @@ export const initialisePerformanceObserver = (infoLogger: InfoLogger): void => { const obs = new PerformanceObserver((perfObserverList) => { const entries = perfObserverList.getEntriesByType('measure'); - entries.forEach((entry) => { - infoLogger.info(new MeasureLoggable(entry)); - }); + infoLogger.info(new MeasuresLoggable(entries)); }); obs.observe({ type: 'measure', buffered: true }); From 59c476eee58888f6cd24740cab982cc68d513eaa Mon Sep 17 00:00:00 2001 From: dyedwiper Date: Mon, 1 Jul 2024 12:01:12 +0200 Subject: [PATCH 21/28] Fix typo --- apps/server/src/modules/tldraw/service/tldraw.ws.service.ts | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) 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 e97e32f5332..1fadacf0bfd 100644 --- a/apps/server/src/modules/tldraw/service/tldraw.ws.service.ts +++ b/apps/server/src/modules/tldraw/service/tldraw.ws.service.ts @@ -35,6 +35,7 @@ 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); @@ -251,7 +252,7 @@ export class TldrawWsService { doc_name: doc.name, doc_awareness_state_total: awarenessStates.size, doc_connection_total: doc.connections.size, - pod_doc_total: this.docs.size, + pod_docs_total: this.docs.size, }, }); } From 37adbf7fecb18e253414cbef4e81ac2f9d59c84e Mon Sep 17 00:00:00 2001 From: dyedwiper Date: Mon, 1 Jul 2024 12:38:05 +0200 Subject: [PATCH 22/28] Make observer a singleton --- .../common/measure-utils/performance-observer.ts | 14 +++++++++----- 1 file changed, 9 insertions(+), 5 deletions(-) diff --git a/apps/server/src/shared/common/measure-utils/performance-observer.ts b/apps/server/src/shared/common/measure-utils/performance-observer.ts index 92ea4c98520..8adca6308f6 100644 --- a/apps/server/src/shared/common/measure-utils/performance-observer.ts +++ b/apps/server/src/shared/common/measure-utils/performance-observer.ts @@ -29,13 +29,17 @@ class InitialisePerformanceObserverLoggable implements Loggable { } } +let observer: PerformanceObserver | null = null; + export const initialisePerformanceObserver = (infoLogger: InfoLogger): void => { infoLogger.info(new InitialisePerformanceObserverLoggable()); - const obs = new PerformanceObserver((perfObserverList) => { - const entries = perfObserverList.getEntriesByType('measure'); - infoLogger.info(new MeasuresLoggable(entries)); - }); + if (observer === null) { + observer = new PerformanceObserver((perfObserverList) => { + const entries = perfObserverList.getEntriesByType('measure'); + infoLogger.info(new MeasuresLoggable(entries)); + }); - obs.observe({ type: 'measure', buffered: true }); + observer.observe({ type: 'measure', buffered: true }); + } }; From a5641d7cee2db73d4b571687f7365e98b505fbe3 Mon Sep 17 00:00:00 2001 From: Cedric Evers <12080057+CeEv@users.noreply.github.com> Date: Mon, 1 Jul 2024 12:42:30 +0200 Subject: [PATCH 23/28] remove todo --- apps/server/src/core/logger/interfaces/loggable.ts | 1 - 1 file changed, 1 deletion(-) diff --git a/apps/server/src/core/logger/interfaces/loggable.ts b/apps/server/src/core/logger/interfaces/loggable.ts index 7b23494a622..005a7f8efe8 100644 --- a/apps/server/src/core/logger/interfaces/loggable.ts +++ b/apps/server/src/core/logger/interfaces/loggable.ts @@ -1,6 +1,5 @@ import { ErrorLogMessage, LogMessage, ValidationErrorLogMessage } from '../types'; -// should be in shared or? export interface Loggable { getLogMessage(): LogMessage | ErrorLogMessage | ValidationErrorLogMessage; } From c5fe421d0d45e39abc14f44381d9c5f791de38c9 Mon Sep 17 00:00:00 2001 From: Cedric Evers <12080057+CeEv@users.noreply.github.com> Date: Mon, 1 Jul 2024 12:48:56 +0200 Subject: [PATCH 24/28] Remove detail from logging context --- apps/server/src/modules/tldraw/tldraw-console.module.ts | 2 +- apps/server/src/modules/tldraw/tldraw-ws.module.ts | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/apps/server/src/modules/tldraw/tldraw-console.module.ts b/apps/server/src/modules/tldraw/tldraw-console.module.ts index caeea438679..80cddece592 100644 --- a/apps/server/src/modules/tldraw/tldraw-console.module.ts +++ b/apps/server/src/modules/tldraw/tldraw-console.module.ts @@ -47,7 +47,7 @@ const defaultMikroOrmOptions: MikroOrmModuleSyncOptions = { export class TldrawConsoleModule { constructor(private readonly logger: Logger, private readonly configService: ConfigService) { if (this.configService.get('PERFORMANCE_MEASURE_ENABLED') === true) { - this.logger.setContext('PerformanceObserver:TldrawConsoleModule'); + 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 f11a9992df9..a4d7ba2ede6 100644 --- a/apps/server/src/modules/tldraw/tldraw-ws.module.ts +++ b/apps/server/src/modules/tldraw/tldraw-ws.module.ts @@ -49,7 +49,7 @@ const defaultMikroOrmOptions: MikroOrmModuleSyncOptions = { export class TldrawWsModule { constructor(private readonly logger: Logger, private readonly configService: ConfigService) { if (this.configService.get('PERFORMANCE_MEASURE_ENABLED') === true) { - this.logger.setContext('PerformanceObserver:TldrawWsModule'); + this.logger.setContext('PerformanceObserver'); initialisePerformanceObserver(this.logger); } } From 7eedadb629733057dfe37cc477b009bc905e3201 Mon Sep 17 00:00:00 2001 From: Cedric Evers <12080057+CeEv@users.noreply.github.com> Date: Mon, 1 Jul 2024 16:28:15 +0200 Subject: [PATCH 25/28] =?UTF-8?q?push=20initial=20test=20setup=20f=C3=BCr?= =?UTF-8?q?=20performance=20observer?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- .../performance-observer.spec.ts | 62 +++++++++++++++++++ .../measure-utils/performance-observer.ts | 4 +- 2 files changed, 64 insertions(+), 2 deletions(-) create mode 100644 apps/server/src/shared/common/measure-utils/performance-observer.spec.ts 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..7ba2ad3aaec --- /dev/null +++ b/apps/server/src/shared/common/measure-utils/performance-observer.spec.ts @@ -0,0 +1,62 @@ +import { PerformanceEntry } from 'node:perf_hooks'; +import { + InitialisePerformanceObserverLoggable, + MeasuresLoggable, + initialisePerformanceObserver, +} from './performance-observer'; + +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()); + }); +}); diff --git a/apps/server/src/shared/common/measure-utils/performance-observer.ts b/apps/server/src/shared/common/measure-utils/performance-observer.ts index 8adca6308f6..784e0c5b928 100644 --- a/apps/server/src/shared/common/measure-utils/performance-observer.ts +++ b/apps/server/src/shared/common/measure-utils/performance-observer.ts @@ -6,7 +6,7 @@ interface InfoLogger { info(input: Loggable): void; } -class MeasuresLoggable implements Loggable { +export class MeasuresLoggable implements Loggable { constructor(private readonly entries: PerformanceEntry[]) {} getLogMessage(): LoggableMessage { @@ -21,7 +21,7 @@ class MeasuresLoggable implements Loggable { } } -class InitialisePerformanceObserverLoggable implements Loggable { +export class InitialisePerformanceObserverLoggable implements Loggable { getLogMessage(): LoggableMessage { return { message: 'Initialise PerformanceObserver...', From 352534b4538bcf477246a7871a894f56e0f0cb1d Mon Sep 17 00:00:00 2001 From: Cedric Evers <12080057+CeEv@users.noreply.github.com> Date: Mon, 1 Jul 2024 16:40:33 +0200 Subject: [PATCH 26/28] add measure test - wip --- .../measure-utils/performance-observer.spec.ts | 16 ++++++++++++++++ 1 file changed, 16 insertions(+) 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 index 7ba2ad3aaec..d188854fb96 100644 --- a/apps/server/src/shared/common/measure-utils/performance-observer.spec.ts +++ b/apps/server/src/shared/common/measure-utils/performance-observer.spec.ts @@ -59,4 +59,20 @@ describe('initialisePerformanceObserver', () => { expect(infoLoggerSpy).toHaveBeenNthCalledWith(1, new InitialisePerformanceObserverLoggable()); }); + + it('should be log messure if it is executed', () => { + const { infoLoggerSpy, mockInfoLogger } = setup(); + + initialisePerformanceObserver(mockInfoLogger); + infoLoggerSpy.mockClear(); + + performance.mark('startMark'); + // execute something + performance.measure('myMeasure', { + start: 'startMark', + detail: { x: 1 }, + }); + + expect(infoLoggerSpy).toHaveBeenCalledWith(MeasuresLoggable); + }); }); From 0e37d8327623badfb4345f52c1b1022d5236c328 Mon Sep 17 00:00:00 2001 From: Cedric Evers <12080057+CeEv@users.noreply.github.com> Date: Tue, 2 Jul 2024 08:36:56 +0200 Subject: [PATCH 27/28] Fix test setup for performance measure test. --- .../performance-observer.spec.ts | 115 +++++++++++------- .../measure-utils/performance-observer.ts | 17 ++- 2 files changed, 84 insertions(+), 48 deletions(-) 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 index d188854fb96..4df8f60c2cd 100644 --- a/apps/server/src/shared/common/measure-utils/performance-observer.spec.ts +++ b/apps/server/src/shared/common/measure-utils/performance-observer.spec.ts @@ -3,76 +3,101 @@ import { InitialisePerformanceObserverLoggable, MeasuresLoggable, initialisePerformanceObserver, + closePerformanceObserver, } from './performance-observer'; -describe('InitialisePerformanceObserverLoggable', () => { - describe('getLogMessage', () => { - it('should be log correct formated message', () => { - const loggable = new InitialisePerformanceObserverLoggable(); +async function wait(timeoutMS: number): Promise { + return new Promise((resolve) => { + setTimeout(resolve, timeoutMS); + }); +} - const log = loggable.getLogMessage(); +async function waitForEventLoopEnd(): Promise { + return new Promise((resolve) => { + process.nextTick(() => { + resolve(undefined); + }); + }); +} + +describe('PerformanceObserver', () => { + afterEach(() => { + jest.restoreAllMocks(); + }); - expect(log).toEqual({ - message: 'Initialise PerformanceObserver...', + 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; + describe('MeasuresLoggable', () => { + describe('getLogMessage', () => { + const setup = () => { + const performanceEntry = { name: 'a', duration: 1, detail: { x: 1 } } as PerformanceEntry; - const loggable = new MeasuresLoggable([performanceEntry, performanceEntry]); + const loggable = new MeasuresLoggable([performanceEntry, performanceEntry]); - return { loggable }; - }; + return { loggable }; + }; - it('should be log correct formated message', () => { - const { loggable } = setup(); + it('should be log correct formated message', () => { + const { loggable } = setup(); - const log = loggable.getLogMessage(); + 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 } }]', + 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: () => {}, + describe('initialisePerformanceObserver', () => { + const setup = () => { + const mockInfoLogger = { + info: () => {}, + }; + const infoLoggerSpy = jest.spyOn(mockInfoLogger, 'info'); + + return { infoLoggerSpy, mockInfoLogger }; }; - const infoLoggerSpy = jest.spyOn(mockInfoLogger, 'info'); - return { infoLoggerSpy, mockInfoLogger }; - }; + it('should be log by execution', () => { + const { infoLoggerSpy, mockInfoLogger } = setup(); - it('should be log by execution', () => { - const { infoLoggerSpy, mockInfoLogger } = setup(); + initialisePerformanceObserver(mockInfoLogger); - initialisePerformanceObserver(mockInfoLogger); + expect(infoLoggerSpy).toHaveBeenNthCalledWith(1, new InitialisePerformanceObserverLoggable()); - 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(); - it('should be log messure if it is executed', () => { - const { infoLoggerSpy, mockInfoLogger } = setup(); + performance.mark('startMark'); + await wait(1); + performance.measure('myMeasure', { + start: 'startMark', + detail: { x: 1 }, + }); - initialisePerformanceObserver(mockInfoLogger); - infoLoggerSpy.mockClear(); + await waitForEventLoopEnd(); + expect(infoLoggerSpy).toHaveBeenNthCalledWith(1, new MeasuresLoggable([])); - performance.mark('startMark'); - // execute something - performance.measure('myMeasure', { - start: 'startMark', - detail: { x: 1 }, + closePerformanceObserver(); }); - - expect(infoLoggerSpy).toHaveBeenCalledWith(MeasuresLoggable); }); }); diff --git a/apps/server/src/shared/common/measure-utils/performance-observer.ts b/apps/server/src/shared/common/measure-utils/performance-observer.ts index 784e0c5b928..6b052b0fd3a 100644 --- a/apps/server/src/shared/common/measure-utils/performance-observer.ts +++ b/apps/server/src/shared/common/measure-utils/performance-observer.ts @@ -31,15 +31,26 @@ export class InitialisePerformanceObserverLoggable implements Loggable { let observer: PerformanceObserver | null = null; -export const initialisePerformanceObserver = (infoLogger: InfoLogger): void => { +export const initialisePerformanceObserver = (infoLogger: InfoLogger): PerformanceObserver => { infoLogger.info(new InitialisePerformanceObserverLoggable()); if (observer === null) { - observer = new PerformanceObserver((perfObserverList) => { - const entries = perfObserverList.getEntriesByType('measure'); + 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; + } }; From ecbbf3cdd55328243e144073c621c7726e62fde8 Mon Sep 17 00:00:00 2001 From: Cedric Evers <12080057+CeEv@users.noreply.github.com> Date: Tue, 2 Jul 2024 08:40:00 +0200 Subject: [PATCH 28/28] fix type --- .../shared/common/measure-utils/performance-observer.spec.ts | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) 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 index 4df8f60c2cd..668ffc7ff29 100644 --- a/apps/server/src/shared/common/measure-utils/performance-observer.spec.ts +++ b/apps/server/src/shared/common/measure-utils/performance-observer.spec.ts @@ -12,10 +12,10 @@ async function wait(timeoutMS: number): Promise { }); } -async function waitForEventLoopEnd(): Promise { +async function waitForEventLoopEnd(): Promise { return new Promise((resolve) => { process.nextTick(() => { - resolve(undefined); + resolve(); }); }); }