diff --git a/.github/workflows/ci-server.yaml b/.github/workflows/ci-server.yaml index 1c119955ad..cea801d2fa 100644 --- a/.github/workflows/ci-server.yaml +++ b/.github/workflows/ci-server.yaml @@ -302,7 +302,7 @@ jobs: strategy: fail-fast: false matrix: - shard: [1, 2, 3, 4, 5, 6, 7, 8, 9, 10] + shard: [1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16] services: postgres: image: postgres:18 @@ -338,7 +338,7 @@ jobs: ANALYTICS_ENABLED: true CLICKHOUSE_URL: "http://default:clickhousePassword@localhost:8123/twenty" CLICKHOUSE_PASSWORD: clickhousePassword - SHARD_COUNTER: 10 + SHARD_COUNTER: 16 steps: - name: Fetch custom Github Actions and base branch history uses: actions/checkout@34e114876b0b11c390a56381ad16ebd13914f8d5 # v4.3.1 diff --git a/packages/twenty-server/.env.test b/packages/twenty-server/.env.test index ffa51bdad7..09c1049908 100644 --- a/packages/twenty-server/.env.test +++ b/packages/twenty-server/.env.test @@ -34,3 +34,5 @@ IS_WORKSPACE_CREATION_V2_ENABLED=true SHOULD_SEED_STANDARD_RECORD_PAGE_LAYOUTS=true LOGIC_FUNCTION_TYPE=LOCAL + +LOG_LEVELS=log,error,warn diff --git a/packages/twenty-server/project.json b/packages/twenty-server/project.json index dbb6dc7bcb..2a3a651d1f 100644 --- a/packages/twenty-server/project.json +++ b/packages/twenty-server/project.json @@ -23,7 +23,7 @@ "options": { "cwd": "packages/twenty-server", "commands": [ - "NODE_ENV=test NODE_OPTIONS=\"--max-old-space-size=12288\" nx jest --config ./jest-integration.config.ts" + "NODE_ENV=test NODE_OPTIONS=\"--max-old-space-size=6144\" nx jest --config ./jest-integration.config.ts --logHeapUsage" ] }, "parallel": false, @@ -31,7 +31,7 @@ "with-db-reset": { "cwd": "packages/twenty-server", "commands": [ - "NODE_ENV=test NODE_OPTIONS=\"--max-old-space-size=12288 --import tsx/esm\" nx database:reset > reset-logs.log && NODE_ENV=test NODE_OPTIONS=\"--max-old-space-size=12288\" nx jest --config ./jest-integration.config.ts" + "NODE_ENV=test NODE_OPTIONS=\"--max-old-space-size=12288 --import tsx/esm\" nx database:reset > reset-logs.log && NODE_ENV=test NODE_OPTIONS=\"--max-old-space-size=6144\" nx jest --config ./jest-integration.config.ts --logHeapUsage" ] } } diff --git a/packages/twenty-server/src/engine/core-modules/application/application-manifest/application-manifest-migration.service.ts b/packages/twenty-server/src/engine/core-modules/application/application-manifest/application-manifest-migration.service.ts index 757694dc03..599a44f885 100644 --- a/packages/twenty-server/src/engine/core-modules/application/application-manifest/application-manifest-migration.service.ts +++ b/packages/twenty-server/src/engine/core-modules/application/application-manifest/application-manifest-migration.service.ts @@ -1,4 +1,4 @@ -import { Injectable, Logger } from '@nestjs/common'; +import { Injectable } from '@nestjs/common'; import { type Manifest } from 'twenty-shared/application'; import { ALL_METADATA_NAME } from 'twenty-shared/metadata'; @@ -13,6 +13,7 @@ import { } from 'src/engine/core-modules/application/application.exception'; import { ApplicationService } from 'src/engine/core-modules/application/application.service'; import { type FlatApplication } from 'src/engine/core-modules/application/types/flat-application.type'; +import { LoggerService } from 'src/engine/core-modules/logger/logger.service'; import { findFlatEntityByUniversalIdentifier } from 'src/engine/metadata-modules/flat-entity/utils/find-flat-entity-by-universal-identifier.util'; import { getMetadataFlatEntityMapsKey } from 'src/engine/metadata-modules/flat-entity/utils/get-metadata-flat-entity-maps-key.util'; import { WorkspaceCacheService } from 'src/engine/workspace-cache/services/workspace-cache.service'; @@ -23,15 +24,12 @@ import { WorkspaceMigration } from 'src/engine/workspace-manager/workspace-migra @Injectable() export class ApplicationManifestMigrationService { - private readonly logger = new Logger( - ApplicationManifestMigrationService.name, - ); - constructor( private readonly workspaceCacheService: WorkspaceCacheService, private readonly workspaceMigrationValidateBuildAndRunService: WorkspaceMigrationValidateBuildAndRunService, private readonly applicationService: ApplicationService, private readonly computeManifestFlatEntityMapsService: ComputeApplicationManifestAllUniversalFlatEntityMapsService, + private readonly logger: LoggerService, ) {} async syncPreInstallLogicFunctionFromManifest({ @@ -155,6 +153,7 @@ export class ApplicationManifestMigrationService { this.logger.log( `Pre-install logic function synced for application ${ownerFlatApplication.universalIdentifier}`, + ApplicationManifestMigrationService.name, ); } @@ -179,7 +178,6 @@ export class ApplicationManifestMigrationService { { workspaceId }, ); - // TODO(install-perf): temporary, remove. const recomputeStart = performance.now(); const cacheResult = await this.workspaceCacheService.getOrRecompute( workspaceId, @@ -190,8 +188,9 @@ export class ApplicationManifestMigrationService { ); const recomputeMs = performance.now() - recomputeStart; - this.logger.log( + this.logger.perf( `[install-perf] syncMetadataFromManifest ALL_METADATA_NAME getOrRecompute flat-maps took ${recomputeMs.toFixed(1)}ms (logicFunctions=${manifest.logicFunctions.length})`, + ApplicationManifestMigrationService.name, ); const { featureFlagsMap, ...existingAllFlatEntityMaps } = cacheResult; @@ -240,8 +239,9 @@ export class ApplicationManifestMigrationService { ); const validateBuildRunMs = performance.now() - validateBuildRunStart; - this.logger.log( + this.logger.perf( `[install-perf] syncMetadataFromManifest validateBuildAndRunWorkspaceMigrationFromTo took ${validateBuildRunMs.toFixed(1)}ms (dryRun=${dryRun}, actions=${validateAndBuildResult.status === 'success' ? validateAndBuildResult.workspaceMigration.actions.length : 'n/a-failed'})`, + ApplicationManifestMigrationService.name, ); if (validateAndBuildResult.status === 'fail') { @@ -253,6 +253,7 @@ export class ApplicationManifestMigrationService { this.logger.log( `Metadata migration ${dryRun ? 'plan computed (dry run)' : 'completed'} for application ${ownerFlatApplication.universalIdentifier}`, + ApplicationManifestMigrationService.name, ); if (!dryRun) { diff --git a/packages/twenty-server/src/engine/core-modules/logger/__tests__/logger.service.spec.ts b/packages/twenty-server/src/engine/core-modules/logger/__tests__/logger.service.spec.ts index f9bc303e28..e076165926 100644 --- a/packages/twenty-server/src/engine/core-modules/logger/__tests__/logger.service.spec.ts +++ b/packages/twenty-server/src/engine/core-modules/logger/__tests__/logger.service.spec.ts @@ -5,14 +5,18 @@ import { LoggerService } from 'src/engine/core-modules/logger/logger.service'; describe('LoggerService', () => { let service: LoggerService; + const driver = { log: jest.fn(), options: { logLevels: [] as string[] } }; beforeEach(async () => { + jest.clearAllMocks(); + driver.options.logLevels = ['log', 'error', 'warn']; + const module: TestingModule = await Test.createTestingModule({ providers: [ LoggerService, { provide: LOGGER_DRIVER, - useValue: {}, + useValue: driver, }, ], }).compile(); @@ -23,4 +27,46 @@ describe('LoggerService', () => { it('should be defined', () => { expect(service).toBeDefined(); }); + + describe('perf', () => { + it('should log through the driver when the performance level is enabled', () => { + driver.options.logLevels = ['log', 'performance']; + + service.perf('message', 'Category'); + + expect(driver.log).toHaveBeenCalledWith('message', 'Category'); + }); + + it('should not log when the performance level is disabled', () => { + driver.options.logLevels = ['log', 'error', 'warn']; + + service.perf('message', 'Category'); + + expect(driver.log).not.toHaveBeenCalled(); + }); + }); + + describe('perfTime / perfTimeEnd', () => { + it('should log the elapsed duration when the performance level is enabled', () => { + driver.options.logLevels = ['performance']; + + service.perfTime('Category', 'label'); + service.perfTimeEnd('Category', 'label'); + + expect(driver.log).toHaveBeenCalledTimes(1); + expect(driver.log).toHaveBeenCalledWith( + expect.stringMatching(/^label: [\d.]+ms$/), + 'Category', + ); + }); + + it('should not log when the performance level is disabled', () => { + driver.options.logLevels = ['log']; + + service.perfTime('Category', 'label'); + service.perfTimeEnd('Category', 'label'); + + expect(driver.log).not.toHaveBeenCalled(); + }); + }); }); diff --git a/packages/twenty-server/src/engine/core-modules/logger/interfaces/logger.interface.ts b/packages/twenty-server/src/engine/core-modules/logger/interfaces/logger.interface.ts index dba05704f1..858d32a479 100644 --- a/packages/twenty-server/src/engine/core-modules/logger/interfaces/logger.interface.ts +++ b/packages/twenty-server/src/engine/core-modules/logger/interfaces/logger.interface.ts @@ -1,12 +1,14 @@ import { type LogLevel } from '@nestjs/common'; +export type TwentyLogLevel = LogLevel | 'performance'; + export enum LoggerDriverType { CONSOLE = 'CONSOLE', } export interface ConsoleDriverFactoryOptions { type: LoggerDriverType.CONSOLE; - logLevels?: LogLevel[]; + logLevels?: TwentyLogLevel[]; } export type LoggerModuleOptions = ConsoleDriverFactoryOptions; diff --git a/packages/twenty-server/src/engine/core-modules/logger/logger.module.ts b/packages/twenty-server/src/engine/core-modules/logger/logger.module.ts index 68793386ba..21bff9f288 100644 --- a/packages/twenty-server/src/engine/core-modules/logger/logger.module.ts +++ b/packages/twenty-server/src/engine/core-modules/logger/logger.module.ts @@ -2,6 +2,7 @@ import { ConsoleLogger, type DynamicModule, Global, + type LogLevel, Module, } from '@nestjs/common'; @@ -54,7 +55,7 @@ export class LoggerModule extends ConfigurableModuleClass { ? new ConsoleLogger() : undefined; - logger?.setLogLevels(logLevels); + logger?.setLogLevels(logLevels as LogLevel[]); return logger; }, diff --git a/packages/twenty-server/src/engine/core-modules/logger/logger.service.ts b/packages/twenty-server/src/engine/core-modules/logger/logger.service.ts index a248ac49a4..d013fd4153 100644 --- a/packages/twenty-server/src/engine/core-modules/logger/logger.service.ts +++ b/packages/twenty-server/src/engine/core-modules/logger/logger.service.ts @@ -7,6 +7,7 @@ import { } from '@nestjs/common'; import { LOGGER_DRIVER } from 'src/engine/core-modules/logger/logger.constants'; +import { type TwentyLogLevel } from 'src/engine/core-modules/logger/interfaces'; type LoggerDriverType = ConsoleLogger & { options?: { @@ -16,8 +17,18 @@ type LoggerDriverType = ConsoleLogger & { @Injectable() export class LoggerService implements LoggerServiceInterface { + private readonly perfTimers = new Map(); + constructor(@Inject(LOGGER_DRIVER) private driver: LoggerDriverType) {} + private isPerfLoggingEnabled() { + return ( + ( + this.driver.options?.logLevels as TwentyLogLevel[] | undefined + )?.includes('performance') ?? false + ); + } + // oxlint-disable-next-line typescript/no-explicit-any log(message: any, category: string, ...optionalParams: any[]) { this.driver.log.apply(this.driver, [message, category, ...optionalParams]); @@ -59,17 +70,42 @@ export class LoggerService implements LoggerServiceInterface { this.driver.setLogLevels?.apply(this.driver, [levels]); } - time(category: string, label: string) { - if (this.driver.options.logLevels?.includes('debug')) { - // oxlint-disable-next-line no-console - console.time(`[${category}] ${label}`); + // oxlint-disable-next-line typescript/no-explicit-any + perf(message: any, category: string, ...optionalParams: any[]) { + if (!this.isPerfLoggingEnabled()) { + return; } + + this.driver.log.apply(this.driver, [message, category, ...optionalParams]); } - timeEnd(category: string, label: string) { - if (this.driver.options.logLevels?.includes('debug')) { - // oxlint-disable-next-line no-console - console.timeEnd(`[${category}] ${label}`); + perfTime(category: string, label: string) { + if (!this.isPerfLoggingEnabled()) { + return; } + + this.perfTimers.set(`${category}::${label}`, performance.now()); + } + + perfTimeEnd(category: string, label: string) { + if (!this.isPerfLoggingEnabled()) { + return; + } + + const key = `${category}::${label}`; + const startedAt = this.perfTimers.get(key); + + if (startedAt === undefined) { + return; + } + + this.perfTimers.delete(key); + + const durationMs = performance.now() - startedAt; + + this.driver.log.apply(this.driver, [ + `${label}: ${durationMs.toFixed(1)}ms`, + category, + ]); } } diff --git a/packages/twenty-server/src/engine/core-modules/twenty-config/config-variables.ts b/packages/twenty-server/src/engine/core-modules/twenty-config/config-variables.ts index 1a95bff542..4c03094e84 100644 --- a/packages/twenty-server/src/engine/core-modules/twenty-config/config-variables.ts +++ b/packages/twenty-server/src/engine/core-modules/twenty-config/config-variables.ts @@ -1,4 +1,4 @@ -import { type LogLevel, Logger } from '@nestjs/common'; +import { Logger } from '@nestjs/common'; import { plainToClass } from 'class-transformer'; import { @@ -23,7 +23,10 @@ import { EmailDriver } from 'src/engine/core-modules/email/enums/email-driver.en import { EmailingDomainDriver } from 'src/engine/core-modules/emailing-domain/drivers/types/emailing-domain-driver.type'; import { ExceptionHandlerDriver } from 'src/engine/core-modules/exception-handler/interfaces'; import { StorageDriverType } from 'src/engine/core-modules/file-storage/interfaces'; -import { LoggerDriverType } from 'src/engine/core-modules/logger/interfaces'; +import { + LoggerDriverType, + type TwentyLogLevel, +} from 'src/engine/core-modules/logger/interfaces'; import { type MeterDriver } from 'src/engine/core-modules/metrics/types/meter-driver.type'; import { CastToLogLevelArray } from 'src/engine/core-modules/twenty-config/decorators/cast-to-log-level-array.decorator'; import { CastToMeterDriverArray } from 'src/engine/core-modules/twenty-config/decorators/cast-to-meter-driver.decorator'; @@ -871,14 +874,15 @@ export class ConfigVariables { @ConfigVariablesMetadata({ group: ConfigVariablesGroup.LOGGING, - description: 'Levels of logging to be captured', + description: + 'Levels of logging to be captured. The "performance" level emits LoggerService perf / perfTime / perfTimeEnd instrumentation.', type: ConfigVariableType.ARRAY, - options: ['log', 'error', 'warn', 'debug'], + options: ['log', 'error', 'warn', 'debug', 'verbose', 'performance'], isEnvOnly: true, }) @CastToLogLevelArray() @IsOptional() - LOG_LEVELS: LogLevel[] = ['log', 'error', 'warn']; + LOG_LEVELS: TwentyLogLevel[] = ['log', 'error', 'warn', 'performance']; @ConfigVariablesMetadata({ group: ConfigVariablesGroup.LOGGING, diff --git a/packages/twenty-server/src/engine/core-modules/twenty-config/decorators/__tests__/cast-to-log-level-array.decorator.spec.ts b/packages/twenty-server/src/engine/core-modules/twenty-config/decorators/__tests__/cast-to-log-level-array.decorator.spec.ts index 25e9d53a57..7973666bbf 100644 --- a/packages/twenty-server/src/engine/core-modules/twenty-config/decorators/__tests__/cast-to-log-level-array.decorator.spec.ts +++ b/packages/twenty-server/src/engine/core-modules/twenty-config/decorators/__tests__/cast-to-log-level-array.decorator.spec.ts @@ -38,6 +38,14 @@ describe('CastToLogLevelArray Decorator', () => { expect(transformedClass.logLevels).toStrictEqual(['verbose']); }); + it('should cast "performance" to ["performance"]', () => { + const transformedClass = plainToClass(TestClass, { + logLevels: 'performance', + }); + + expect(transformedClass.logLevels).toStrictEqual(['performance']); + }); + it('should cast "verbose,error,warn" to ["verbose", "error", "warn"]', () => { const transformedClass = plainToClass(TestClass, { logLevels: 'verbose,error,warn', @@ -52,7 +60,7 @@ describe('CastToLogLevelArray Decorator', () => { it('should throw on invalid level "toto" with clear error message', () => { expect(() => plainToClass(TestClass, { logLevels: 'toto' })).toThrow( - 'Invalid log level(s): toto. Valid levels are: log, error, warn, debug, verbose', + 'Invalid log level(s): toto. Valid levels are: log, error, warn, debug, verbose, performance', ); }); @@ -60,7 +68,7 @@ describe('CastToLogLevelArray Decorator', () => { expect(() => plainToClass(TestClass, { logLevels: 'verbose,error,toto' }), ).toThrow( - 'Invalid log level(s): toto. Valid levels are: log, error, warn, debug, verbose', + 'Invalid log level(s): toto. Valid levels are: log, error, warn, debug, verbose, performance', ); }); }); diff --git a/packages/twenty-server/src/engine/core-modules/twenty-config/decorators/cast-to-log-level-array.decorator.ts b/packages/twenty-server/src/engine/core-modules/twenty-config/decorators/cast-to-log-level-array.decorator.ts index 146b16d1dd..a2a0e0ab5e 100644 --- a/packages/twenty-server/src/engine/core-modules/twenty-config/decorators/cast-to-log-level-array.decorator.ts +++ b/packages/twenty-server/src/engine/core-modules/twenty-config/decorators/cast-to-log-level-array.decorator.ts @@ -1,6 +1,13 @@ import { Transform } from 'class-transformer'; -const VALID_LOG_LEVELS = ['log', 'error', 'warn', 'debug', 'verbose']; +const VALID_LOG_LEVELS = [ + 'log', + 'error', + 'warn', + 'debug', + 'verbose', + 'performance', +]; export const CastToLogLevelArray = () => Transform(({ value }: { value: string }) => toLogLevelArray(value)); diff --git a/packages/twenty-server/src/engine/workspace-manager/workspace-migration/services/workspace-migration-validate-build-and-run-service.ts b/packages/twenty-server/src/engine/workspace-manager/workspace-migration/services/workspace-migration-validate-build-and-run-service.ts index 118a79a81a..b21325620a 100644 --- a/packages/twenty-server/src/engine/workspace-manager/workspace-migration/services/workspace-migration-validate-build-and-run-service.ts +++ b/packages/twenty-server/src/engine/workspace-manager/workspace-migration/services/workspace-migration-validate-build-and-run-service.ts @@ -1,4 +1,4 @@ -import { Injectable, Logger } from '@nestjs/common'; +import { Injectable } from '@nestjs/common'; import { AllMetadataName, @@ -7,6 +7,7 @@ import { import { isDefined } from 'twenty-shared/utils'; import { FlatApplicationCacheMaps } from 'src/engine/core-modules/application/types/flat-application-cache-maps.type'; +import { LoggerService } from 'src/engine/core-modules/logger/logger.service'; import { TwentyConfigService } from 'src/engine/core-modules/twenty-config/twenty-config.service'; import { ALL_MANY_TO_ONE_METADATA_RELATIONS } from 'src/engine/metadata-modules/flat-entity/constant/all-many-to-one-metadata-relations.constant'; import { createEmptyFlatEntityMaps } from 'src/engine/metadata-modules/flat-entity/constant/create-empty-flat-entity-maps.constant'; @@ -53,9 +54,6 @@ type ValidateBuildAndRunWorkspaceMigrationFromMatriceArgs = { @Injectable() export class WorkspaceMigrationValidateBuildAndRunService { - private readonly logger = new Logger( - WorkspaceMigrationValidateBuildAndRunService.name, - ); private readonly isDebugEnabled: boolean; constructor( @@ -63,6 +61,7 @@ export class WorkspaceMigrationValidateBuildAndRunService { private readonly workspaceMigrationBuildOrchestratorService: WorkspaceMigrationBuildOrchestratorService, private readonly workspaceCacheService: WorkspaceCacheService, private readonly metadataEventEmitter: MetadataEventEmitter, + private readonly logger: LoggerService, twentyConfigService: TwentyConfigService, ) { const logLevels = twentyConfigService.get('LOG_LEVELS'); @@ -369,13 +368,15 @@ export class WorkspaceMigrationValidateBuildAndRunService { const { idByUniversalIdentifierByMetadataName, dryRun, ...buildArgs } = args; - // TODO(install-perf): temporary, remove. const buildStart = performance.now(); const validateAndBuildResult = await this.workspaceMigrationBuildOrchestratorService .buildWorkspaceMigration(buildArgs) .catch((error) => { - this.logger.error(error); + this.logger.error( + error, + WorkspaceMigrationValidateBuildAndRunService.name, + ); throw new WorkspaceMigrationV2Exception( error.message, WorkspaceMigrationV2ExceptionCode.BUILDER_INTERNAL_SERVER_ERROR, @@ -383,13 +384,17 @@ export class WorkspaceMigrationValidateBuildAndRunService { }); const buildMs = performance.now() - buildStart; - this.logger.log( + this.logger.perf( `[install-perf] buildWorkspaceMigration took ${buildMs.toFixed(1)}ms (status=${validateAndBuildResult.status})`, + WorkspaceMigrationValidateBuildAndRunService.name, ); if (validateAndBuildResult.status === 'fail') { if (this.isDebugEnabled) { - this.logger.debug(JSON.stringify(validateAndBuildResult, null, 2)); + this.logger.debug?.( + JSON.stringify(validateAndBuildResult, null, 2), + WorkspaceMigrationValidateBuildAndRunService.name, + ); } return validateAndBuildResult; @@ -418,8 +423,9 @@ export class WorkspaceMigrationValidateBuildAndRunService { (actionCountsByTypeAndMetadataName[key] ?? 0) + 1; } - this.logger.log( + this.logger.perf( `[install-perf] validateBuildAndRunWorkspaceMigrationFromTo running ${workspaceMigration.actions.length} actions: ${JSON.stringify(actionCountsByTypeAndMetadataName)}`, + WorkspaceMigrationValidateBuildAndRunService.name, ); const runStart = performance.now(); @@ -430,8 +436,9 @@ export class WorkspaceMigrationValidateBuildAndRunService { }); const runMs = performance.now() - runStart; - this.logger.log( + this.logger.perf( `[install-perf] workspaceMigrationRunnerService.run took ${runMs.toFixed(1)}ms for ${workspaceMigration.actions.length} actions`, + WorkspaceMigrationValidateBuildAndRunService.name, ); this.metadataEventEmitter.emitMetadataEvents({ diff --git a/packages/twenty-server/src/engine/workspace-manager/workspace-migration/workspace-migration-builder/services/workspace-entity-migration-builder.service.ts b/packages/twenty-server/src/engine/workspace-manager/workspace-migration/workspace-migration-builder/services/workspace-entity-migration-builder.service.ts index 86355697ee..2a73347cc5 100644 --- a/packages/twenty-server/src/engine/workspace-manager/workspace-migration/workspace-migration-builder/services/workspace-entity-migration-builder.service.ts +++ b/packages/twenty-server/src/engine/workspace-manager/workspace-migration/workspace-migration-builder/services/workspace-entity-migration-builder.service.ts @@ -70,8 +70,11 @@ export abstract class WorkspaceEntityMigrationBuilderService< additionalCacheDataMaps, workspaceId, }: ValidateAndBuildArgs): ValidateAndBuildReturnType { - this.logger.time(`EntityBuilder ${this.metadataName}`, 'validateAndBuild'); - this.logger.time( + this.logger.perfTime( + `EntityBuilder ${this.metadataName}`, + 'validateAndBuild', + ); + this.logger.perfTime( `EntityBuilder ${this.metadataName}`, 'matrix computation', ); @@ -94,11 +97,14 @@ export abstract class WorkspaceEntityMigrationBuilderService< buildOptions, }); - this.logger.timeEnd( + this.logger.perfTimeEnd( `EntityBuilder ${this.metadataName}`, 'matrix computation', ); - this.logger.time(`EntityBuilder ${this.metadataName}`, 'entity processing'); + this.logger.perfTime( + `EntityBuilder ${this.metadataName}`, + 'entity processing', + ); const flatEntityMapsKey = getMetadataFlatEntityMapsKey(this.metadataName); const actionsResult = getMetadataEmptyWorkspaceMigrationActionRecord( @@ -107,7 +113,7 @@ export abstract class WorkspaceEntityMigrationBuilderService< const allValidationResult: FailedFlatEntityValidateAndBuild['errors'] = []; - this.logger.time( + this.logger.perfTime( `EntityBuilder ${this.metadataName}`, 'deletion validation', ); @@ -173,11 +179,14 @@ export abstract class WorkspaceEntityMigrationBuilderService< ); } - this.logger.timeEnd( + this.logger.perfTimeEnd( `EntityBuilder ${this.metadataName}`, 'deletion validation', ); - this.logger.time(`EntityBuilder ${this.metadataName}`, 'update validation'); + this.logger.perfTime( + `EntityBuilder ${this.metadataName}`, + 'update validation', + ); for (const flatEntityToUpdateUniversalIdentifier in updatedFlatEntityMaps.byUniversalIdentifier) { const flatEntityUpdate = @@ -257,7 +266,7 @@ export abstract class WorkspaceEntityMigrationBuilderService< ); } - this.logger.timeEnd( + this.logger.perfTimeEnd( `EntityBuilder ${this.metadataName}`, 'update validation', ); @@ -266,7 +275,7 @@ export abstract class WorkspaceEntityMigrationBuilderService< createdFlatEntityMaps, ); - this.logger.time( + this.logger.perfTime( `EntityBuilder ${this.metadataName}`, 'creation validation', ); @@ -338,11 +347,11 @@ export abstract class WorkspaceEntityMigrationBuilderService< actionsResult.create.push(formattedNewCreateAction); } - this.logger.timeEnd( + this.logger.perfTimeEnd( `EntityBuilder ${this.metadataName}`, 'creation validation', ); - this.logger.timeEnd( + this.logger.perfTimeEnd( `EntityBuilder ${this.metadataName}`, 'entity processing', ); @@ -354,7 +363,7 @@ export abstract class WorkspaceEntityMigrationBuilderService< }; } - this.logger.timeEnd( + this.logger.perfTimeEnd( `EntityBuilder ${this.metadataName}`, 'validateAndBuild', ); diff --git a/packages/twenty-server/src/engine/workspace-manager/workspace-migration/workspace-migration-runner/action-handlers/logic-function/services/update-logic-function-action-handler.service.ts b/packages/twenty-server/src/engine/workspace-manager/workspace-migration/workspace-migration-runner/action-handlers/logic-function/services/update-logic-function-action-handler.service.ts index 184592c144..adeb8f91f4 100644 --- a/packages/twenty-server/src/engine/workspace-manager/workspace-migration/workspace-migration-runner/action-handlers/logic-function/services/update-logic-function-action-handler.service.ts +++ b/packages/twenty-server/src/engine/workspace-manager/workspace-migration/workspace-migration-runner/action-handlers/logic-function/services/update-logic-function-action-handler.service.ts @@ -106,7 +106,6 @@ export class UpdateLogicFunctionActionHandlerService extends WorkspaceMigrationR }); if (builtPathChanged) { - // TODO(install-perf): temporary, remove. const deleteFileStart = performance.now(); await this.fileStorageService.deleteFile({ @@ -118,7 +117,7 @@ export class UpdateLogicFunctionActionHandlerService extends WorkspaceMigrationR const deleteFileMs = performance.now() - deleteFileStart; - this.logger.log( + this.logger.perf( `[install-perf] update logicFunction fileStorageService.deleteFile took ${deleteFileMs.toFixed(1)}ms (fnId=${entityId})`, UpdateLogicFunctionActionHandlerService.name, ); diff --git a/packages/twenty-server/src/engine/workspace-manager/workspace-migration/workspace-migration-runner/interfaces/workspace-migration-runner-action-handler-service.interface.ts b/packages/twenty-server/src/engine/workspace-manager/workspace-migration/workspace-migration-runner/interfaces/workspace-migration-runner-action-handler-service.interface.ts index 169fba4c94..b2434500b9 100644 --- a/packages/twenty-server/src/engine/workspace-manager/workspace-migration/workspace-migration-runner/interfaces/workspace-migration-runner-action-handler-service.interface.ts +++ b/packages/twenty-server/src/engine/workspace-manager/workspace-migration/workspace-migration-runner/interfaces/workspace-migration-runner-action-handler-service.interface.ts @@ -310,12 +310,12 @@ export abstract class BaseWorkspaceMigrationRunnerActionHandlerService< label: string; method: () => Promise; }): Promise { - this.logger.time( + this.logger.perfTime( 'BaseWorkspaceMigrationRunnerActionHandlerService', `${this.actionType}_${this.metadataName} ${label}`, ); await method(); - this.logger.timeEnd( + this.logger.perfTimeEnd( 'BaseWorkspaceMigrationRunnerActionHandlerService', `${this.actionType}_${this.metadataName} ${label}`, ); diff --git a/packages/twenty-server/src/engine/workspace-manager/workspace-migration/workspace-migration-runner/services/workspace-migration-runner.service.ts b/packages/twenty-server/src/engine/workspace-manager/workspace-migration/workspace-migration-runner/services/workspace-migration-runner.service.ts index 6fd484d048..62476baf5f 100644 --- a/packages/twenty-server/src/engine/workspace-manager/workspace-migration/workspace-migration-runner/services/workspace-migration-runner.service.ts +++ b/packages/twenty-server/src/engine/workspace-manager/workspace-migration/workspace-migration-runner/services/workspace-migration-runner.service.ts @@ -128,7 +128,7 @@ export class WorkspaceMigrationRunnerService { allFlatEntityMapsKeys: (keyof AllFlatEntityMaps)[]; workspaceId: string; }): Promise { - this.logger.time( + this.logger.perfTime( 'Runner', `Cache invalidation ${allFlatEntityMapsKeys.join()}`, ); @@ -161,13 +161,12 @@ export class WorkspaceMigrationRunnerService { ); } - this.logger.timeEnd( + this.logger.perfTimeEnd( 'Runner', `Cache invalidation ${allFlatEntityMapsKeys.join()}`, ); } - // TODO(install-perf): temporary, remove. Snapshots blocking DB sessions on a fresh connection. private async logBlockingDbActivity(): Promise { try { // Metadata only (no query text) to avoid logging literals from other sessions. @@ -216,8 +215,8 @@ export class WorkspaceMigrationRunnerService { }); } - this.logger.time('Runner', 'Total execution'); - this.logger.time('Runner', 'Initial cache retrieval'); + this.logger.perfTime('Runner', 'Total execution'); + this.logger.perfTime('Runner', 'Initial cache retrieval'); const initialCacheRetrievalStart = performance.now(); @@ -248,12 +247,12 @@ export class WorkspaceMigrationRunnerService { flatMapsKeys: allFlatEntityMapsKeys, }); - this.logger.timeEnd('Runner', 'Initial cache retrieval'); + this.logger.perfTimeEnd('Runner', 'Initial cache retrieval'); const initialCacheRetrievalMs = performance.now() - initialCacheRetrievalStart; - this.logger.log( + this.logger.perf( `[install-perf] Runner initial cache retrieval (getOrRecomputeManyOrAllFlatEntityMaps) took ${initialCacheRetrievalMs.toFixed(1)}ms for ${allFlatEntityMapsKeys.length} flat-maps keys`, 'Runner', ); @@ -278,21 +277,19 @@ export class WorkspaceMigrationRunnerService { }); } - this.logger.time('Runner', 'Transaction execution'); + this.logger.perfTime('Runner', 'Transaction execution'); await queryRunner.connect(); await queryRunner.startTransaction(); const allMetadataEvents: MetadataEvent[] = []; - // TODO(install-perf): temporary, remove. const transactionStart = performance.now(); let slowestActionMs = 0; let slowestActionLabel = 'n/a'; let actionCount = 0; try { - // TODO(install-perf): temporary, remove. Fail fast on lock waits (< 10s query_timeout) for a clear error. await queryRunner.query(`SET LOCAL lock_timeout = '8s'`); for (const action of actions) { @@ -321,7 +318,7 @@ export class WorkspaceMigrationRunnerService { } if (actionMs > 50) { - this.logger.log( + this.logger.perf( `[install-perf] slow action ${action.type}:${action.metadataName} took ${actionMs.toFixed(1)}ms`, 'Runner', ); @@ -342,14 +339,13 @@ export class WorkspaceMigrationRunnerService { const commitMs = performance.now() - commitStart; const transactionMs = performance.now() - transactionStart; - this.logger.log( + this.logger.perf( `[install-perf] Runner transaction summary: ${actionCount} actions, total transaction ${transactionMs.toFixed(1)}ms (commit ${commitMs.toFixed(1)}ms), slowest action ${slowestActionLabel} ${slowestActionMs.toFixed(1)}ms`, 'Runner', ); - this.logger.timeEnd('Runner', 'Transaction execution'); + this.logger.perfTimeEnd('Runner', 'Transaction execution'); } catch (error) { - // TODO(install-perf): temporary, remove. Logs the real cause + blockers and guards the rollback. this.logger.error( `[install-perf] migration failed after ${actionCount} action(s): ${ error instanceof Error ? error.message : String(error) @@ -431,7 +427,7 @@ export class WorkspaceMigrationRunnerService { const postCommitInvalidateMs = performance.now() - postCommitInvalidateStart; - this.logger.log( + this.logger.perf( `[install-perf] Runner post-commit invalidateCache took ${postCommitInvalidateMs.toFixed(1)}ms for ${allFlatEntityMapsKeys.length} flat-maps keys`, 'Runner', ); @@ -440,7 +436,7 @@ export class WorkspaceMigrationRunnerService { allFlatEntityMapsKeys.includes('flatObjectMetadataMaps') || allFlatEntityMapsKeys.includes('flatFieldMetadataMaps'); - this.logger.timeEnd('Runner', 'Total execution'); + this.logger.perfTimeEnd('Runner', 'Total execution'); return { allFlatEntityMaps,