From fcaf2b4d9b1ca68cb544b4b96aef1673b811f8f4 Mon Sep 17 00:00:00 2001 From: Charles Bochet Date: Tue, 9 Jun 2026 15:57:25 +0200 Subject: [PATCH] chore(twenty-server): temporary instrumentation for app-install 504 (#21365) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## Why App installs on cloud intermittently fail with a 504, surfacing in Sentry as `Migration action 'update' for 'logicFunction' failed` + `Failed to rollback transaction: Query runner already released`. This is **temporary instrumentation** to pin down where the time goes — to be reverted once the bottleneck is fixed. Everything is greppable via `[install-perf]` and marked `// TODO(install-perf)`. ## What the local repro already told us I instrumented the manifest-sync/migration path and ran a local harness (new skipped spec) installing **1 / 8 / 30 logic functions**, for both create and the checksum-bump **update** (the incident path): | stage (N=30, update) | ms | |---|---| | flat-maps recompute | ~1 | | build migration | ~11 | | transaction (all actions + commit) | ~79 | | post-commit cache invalidate | ~6 | | **full sync** | **~135** | Nothing approached 1s, let alone 10s; no slow queries logged. So the migration/cache code is **not** the algorithmic cause. Given the in-transaction `UPDATE ... WHERE id=?` is intrinsically fast, a >10s in prod almost certainly means it was **blocked on a lock**, and the 10s node-pg `query_timeout` (`core.datasource.ts`) then killed the connection → the observed errors + 504. Local can't reproduce prod lock contention / table sizes, hence this instrumentation. ## What this adds (all `TODO`-marked) - **hrtime per-stage timing** — flat-maps recompute, build vs run, per-action (`>50ms`), transaction summary, post-commit cache invalidation. Uses `process.hrtime` because the integration harness enables fake timers (so `Date.now()` is useless there). - **`maxQueryExecutionTime`** slow-query logging on the core datasource (logs the offending SQL). - **Scoped `SET LOCAL lock_timeout = '8s'`** on the migration transaction (below the 10s `query_timeout`) → a blocked action fails fast with a clear *"canceling statement due to lock timeout"* instead of the opaque connection kill. - **Best-effort `pg_stat_activity` snapshot on failure** (on a fresh pooled connection) to identify the blocking session, plus a **guarded rollback** so a released connection stops masking the real error. - **Skipped local perf harness** (`logic-function-install-performance.integration-spec.ts`) — run manually with `nx test:integration:with-db-reset -- --testPathPattern "logic-function-install-performance"`. ## How we'll use it Deploy, reproduce the failing install, and read the `[install-perf]` logs: the per-action timing names the action, the `lock_timeout` message + `pg_stat_activity` snapshot name the **blocking** query/PID. Then revert this PR and fix the actual contention. Typecheck (`nx typecheck twenty-server`) is clean. --- .../application-manifest-migration.service.ts | 13 ++ ...igration-validate-build-and-run-service.ts | 26 +++ ...e-logic-function-action-handler.service.ts | 10 ++ .../workspace-migration-runner.service.ts | 114 ++++++++++++- ...on-install-performance.integration-spec.ts | 151 ++++++++++++++++++ 5 files changed, 309 insertions(+), 5 deletions(-) create mode 100644 packages/twenty-server/test/integration/metadata/suites/application/logic-function-install-performance.integration-spec.ts 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 e8e4f0f267..757694dc03 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 @@ -179,6 +179,8 @@ export class ApplicationManifestMigrationService { { workspaceId }, ); + // TODO(install-perf): temporary, remove. + const recomputeStart = performance.now(); const cacheResult = await this.workspaceCacheService.getOrRecompute( workspaceId, [ @@ -186,6 +188,11 @@ export class ApplicationManifestMigrationService { 'featureFlagsMap', ], ); + const recomputeMs = performance.now() - recomputeStart; + + this.logger.log( + `[install-perf] syncMetadataFromManifest ALL_METADATA_NAME getOrRecompute flat-maps took ${recomputeMs.toFixed(1)}ms (logicFunctions=${manifest.logicFunctions.length})`, + ); const { featureFlagsMap, ...existingAllFlatEntityMaps } = cacheResult; @@ -211,6 +218,7 @@ export class ApplicationManifestMigrationService { fromAllFlatEntityMaps: existingAllFlatEntityMaps, }); + const validateBuildRunStart = performance.now(); const validateAndBuildResult = await this.workspaceMigrationValidateBuildAndRunService.validateBuildAndRunWorkspaceMigrationFromTo( { @@ -230,6 +238,11 @@ export class ApplicationManifestMigrationService { dryRun, }, ); + const validateBuildRunMs = performance.now() - validateBuildRunStart; + + this.logger.log( + `[install-perf] syncMetadataFromManifest validateBuildAndRunWorkspaceMigrationFromTo took ${validateBuildRunMs.toFixed(1)}ms (dryRun=${dryRun}, actions=${validateAndBuildResult.status === 'success' ? validateAndBuildResult.workspaceMigration.actions.length : 'n/a-failed'})`, + ); if (validateAndBuildResult.status === 'fail') { throw new WorkspaceMigrationBuilderException( 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 1282bd57bf..118a79a81a 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 @@ -369,6 +369,8 @@ export class WorkspaceMigrationValidateBuildAndRunService { const { idByUniversalIdentifierByMetadataName, dryRun, ...buildArgs } = args; + // TODO(install-perf): temporary, remove. + const buildStart = performance.now(); const validateAndBuildResult = await this.workspaceMigrationBuildOrchestratorService .buildWorkspaceMigration(buildArgs) @@ -379,6 +381,11 @@ export class WorkspaceMigrationValidateBuildAndRunService { WorkspaceMigrationV2ExceptionCode.BUILDER_INTERNAL_SERVER_ERROR, ); }); + const buildMs = performance.now() - buildStart; + + this.logger.log( + `[install-perf] buildWorkspaceMigration took ${buildMs.toFixed(1)}ms (status=${validateAndBuildResult.status})`, + ); if (validateAndBuildResult.status === 'fail') { if (this.isDebugEnabled) { @@ -402,11 +409,30 @@ export class WorkspaceMigrationValidateBuildAndRunService { }; } + const actionCountsByTypeAndMetadataName: Record = {}; + + for (const action of workspaceMigration.actions) { + const key = `${action.type}:${action.metadataName}`; + + actionCountsByTypeAndMetadataName[key] = + (actionCountsByTypeAndMetadataName[key] ?? 0) + 1; + } + + this.logger.log( + `[install-perf] validateBuildAndRunWorkspaceMigrationFromTo running ${workspaceMigration.actions.length} actions: ${JSON.stringify(actionCountsByTypeAndMetadataName)}`, + ); + + const runStart = performance.now(); const { hasSchemaMetadataChanged, metadataEvents } = await this.workspaceMigrationRunnerService.run({ workspaceId: args.workspaceId, workspaceMigration, }); + const runMs = performance.now() - runStart; + + this.logger.log( + `[install-perf] workspaceMigrationRunnerService.run took ${runMs.toFixed(1)}ms for ${workspaceMigration.actions.length} actions`, + ); this.metadataEventEmitter.emitMetadataEvents({ metadataEvents: metadataEvents, 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 0f5a9bf03d..184592c144 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,12 +106,22 @@ export class UpdateLogicFunctionActionHandlerService extends WorkspaceMigrationR }); if (builtPathChanged) { + // TODO(install-perf): temporary, remove. + const deleteFileStart = performance.now(); + await this.fileStorageService.deleteFile({ workspaceId, applicationUniversalIdentifier, fileFolder: FileFolder.BuiltLogicFunction, resourcePath: existingLogicFunction.builtHandlerPath, }); + + const deleteFileMs = performance.now() - deleteFileStart; + + this.logger.log( + `[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/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 4041c2f46e..6fd484d048 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 @@ -167,6 +167,36 @@ export class WorkspaceMigrationRunnerService { ); } + // 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. + const rows = await this.coreDataSource.query( + `SELECT pid, state, wait_event_type, wait_event, + now() - query_start AS running_for, pg_blocking_pids(pid) AS blocked_by + FROM pg_stat_activity + WHERE datname = current_database() + AND state <> 'idle' + AND pid <> pg_backend_pid() + ORDER BY query_start ASC`, + ); + + this.logger.error( + `[install-perf] active DB sessions at failure: ${JSON.stringify(rows)}`, + 'Runner', + ); + } catch (snapshotError) { + this.logger.error( + `[install-perf] could not snapshot pg_stat_activity: ${ + snapshotError instanceof Error + ? snapshotError.message + : String(snapshotError) + }`, + 'Runner', + ); + } + } + run = async ({ workspaceMigration: { actions, applicationUniversalIdentifier }, workspaceId, @@ -189,6 +219,8 @@ export class WorkspaceMigrationRunnerService { this.logger.time('Runner', 'Total execution'); this.logger.time('Runner', 'Initial cache retrieval'); + const initialCacheRetrievalStart = performance.now(); + const queryRunner = this.coreDataSource.createQueryRunner(); const actionMetadataNames = [ @@ -218,6 +250,14 @@ export class WorkspaceMigrationRunnerService { this.logger.timeEnd('Runner', 'Initial cache retrieval'); + const initialCacheRetrievalMs = + performance.now() - initialCacheRetrievalStart; + + this.logger.log( + `[install-perf] Runner initial cache retrieval (getOrRecomputeManyOrAllFlatEntityMaps) took ${initialCacheRetrievalMs.toFixed(1)}ms for ${allFlatEntityMapsKeys.length} flat-maps keys`, + 'Runner', + ); + const { flatApplicationMaps } = await this.workspaceCacheService.getOrRecompute(workspaceId, [ 'flatApplicationMaps', @@ -245,8 +285,18 @@ export class WorkspaceMigrationRunnerService { 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) { + const actionStart = performance.now(); const { partialOptimisticCache, metadataEvents } = await this.workspaceMigrationRunnerActionHandlerRegistry.executeActionHandler( { @@ -261,6 +311,22 @@ export class WorkspaceMigrationRunnerService { }, ); + const actionMs = performance.now() - actionStart; + + actionCount += 1; + + if (actionMs > slowestActionMs) { + slowestActionMs = actionMs; + slowestActionLabel = `${action.type}:${action.metadataName}`; + } + + if (actionMs > 50) { + this.logger.log( + `[install-perf] slow action ${action.type}:${action.metadataName} took ${actionMs.toFixed(1)}ms`, + 'Runner', + ); + } + allFlatEntityMaps = { ...allFlatEntityMaps, ...partialOptimisticCache, @@ -269,16 +335,44 @@ export class WorkspaceMigrationRunnerService { allMetadataEvents.push(...metadataEvents); } + const commitStart = performance.now(); + await queryRunner.commitTransaction(); + const commitMs = performance.now() - commitStart; + const transactionMs = performance.now() - transactionStart; + + this.logger.log( + `[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'); } catch (error) { - await queryRunner.rollbackTransaction().catch((rollbackError) => - // oxlint-disable-next-line no-console - console.trace( - `Failed to rollback transaction: ${rollbackError.message}`, - ), + // 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) + }`, + 'Runner', ); + await this.logBlockingDbActivity(); + + if (queryRunner.isTransactionActive && !queryRunner.isReleased) { + await queryRunner + .rollbackTransaction() + .catch((rollbackError) => + this.logger.error( + `[install-perf] rollback failed: ${rollbackError.message}`, + 'Runner', + ), + ); + } else { + this.logger.error( + `[install-perf] skipping rollback (txnActive=${queryRunner.isTransactionActive} released=${queryRunner.isReleased})`, + 'Runner', + ); + } const invertedActions = [...actions].reverse(); @@ -320,6 +414,8 @@ export class WorkspaceMigrationRunnerService { await queryRunner.release(); } + const postCommitInvalidateStart = performance.now(); + try { await this.invalidateCache({ allFlatEntityMapsKeys, @@ -332,6 +428,14 @@ export class WorkspaceMigrationRunnerService { ); } + const postCommitInvalidateMs = + performance.now() - postCommitInvalidateStart; + + this.logger.log( + `[install-perf] Runner post-commit invalidateCache took ${postCommitInvalidateMs.toFixed(1)}ms for ${allFlatEntityMapsKeys.length} flat-maps keys`, + 'Runner', + ); + const hasSchemaMetadataChanged = allFlatEntityMapsKeys.includes('flatObjectMetadataMaps') || allFlatEntityMapsKeys.includes('flatFieldMetadataMaps'); diff --git a/packages/twenty-server/test/integration/metadata/suites/application/logic-function-install-performance.integration-spec.ts b/packages/twenty-server/test/integration/metadata/suites/application/logic-function-install-performance.integration-spec.ts new file mode 100644 index 0000000000..b9545624ae --- /dev/null +++ b/packages/twenty-server/test/integration/metadata/suites/application/logic-function-install-performance.integration-spec.ts @@ -0,0 +1,151 @@ +import { buildBaseManifest } from 'test/integration/metadata/suites/application/utils/build-base-manifest.util'; +import { cleanupApplicationAndAppRegistration } from 'test/integration/metadata/suites/application/utils/cleanup-application-and-app-registration.util'; +import { setupApplicationForSync } from 'test/integration/metadata/suites/application/utils/setup-application-for-sync.util'; +import { syncApplication } from 'test/integration/metadata/suites/application/utils/sync-application.util'; +import { + type LogicFunctionManifest, + type Manifest, +} from 'twenty-shared/application'; +import { v4 as uuidv4 } from 'uuid'; + +/** + * Performance harness for installing / updating many logic functions through + * application manifest sync. The goal is to find what could take >10s in prod + * (which trips the node-postgres `query_timeout` in core.datasource.ts and + * produces "Migration action 'update' for 'logicFunction' failed" + 504). + * + * IMPORTANT: the integration harness boots the NestJS app in-process with + * `fakeTimers.enableGlobally: true`. We call `jest.useRealTimers()` for the whole + * suite so timing (`performance.now()`) is real and cache-lock retry delays etc. + * do not hang. + */ + +// Real timers for the whole suite — see note above. +jest.useRealTimers(); + +jest.setTimeout(120000); + +const FN_COUNTS = [1, 8, 30]; + +// Stable universalIdentifiers across versions so the second sync exercises +// UPDATE (the actual incident), not CREATE+DELETE. +const buildManifest = ({ + appId, + roleId, + universalIdentifiers, + checksumVersion, +}: { + appId: string; + roleId: string; + universalIdentifiers: string[]; + checksumVersion: 'v1' | 'v2'; +}): Manifest => { + const logicFunctions: LogicFunctionManifest[] = universalIdentifiers.map( + (universalIdentifier, i) => ({ + universalIdentifier, + name: `PerfFn${i}`, + description: `Perf logic function ${i}`, + handlerName: 'handler', + sourceHandlerPath: `src/fn-${i}.ts`, + builtHandlerPath: `dist/fn-${i}.mjs`, + builtHandlerChecksum: `checksum-${i}-${checksumVersion}`, + httpRouteTriggerSettings: { + path: `/fn-${i}`, + httpMethod: 'GET', + isAuthRequired: true, + }, + }), + ); + + return buildBaseManifest({ + appId, + roleId, + overrides: { logicFunctions }, + }); +}; + +const timeSync = async ( + label: string, + manifest: Manifest, +): Promise => { + const start = performance.now(); + + await syncApplication({ manifest, expectToFail: false }); + + const ms = performance.now() - start; + + // oxlint-disable-next-line no-console + console.log(`[install-perf][test] ${label} took ${ms.toFixed(1)}ms`); + + return ms; +}; + +// TODO(install-perf): temporary manual perf harness, remove. Skipped in CI. +describe.skip('Logic function install performance', () => { + it.each(FN_COUNTS)( + 'create + update sync with %i logic functions', + async (count) => { + const appId = uuidv4(); + const roleId = uuidv4(); + const universalIdentifiers = Array.from({ length: count }, () => + uuidv4(), + ); + + await setupApplicationForSync({ + applicationUniversalIdentifier: appId, + name: `Perf App ${count}`, + description: `Perf app with ${count} logic functions`, + sourcePath: `perf-app-${count}`, + }); + + jest.useRealTimers(); + + try { + // No built-handler file upload is needed: the migration create/update + // handlers never read the built file for LIVE functions (prebuilt + // install is skipped), and uploading N files would trip the file-upload + // rate limiter (30 per 30s). We only measure migration + cache cost. + + // oxlint-disable-next-line no-console + console.log( + `[install-perf][test] ===== N=${count} : FIRST SYNC (create ${count} functions) =====`, + ); + + const createMs = await timeSync( + `N=${count} create sync`, + buildManifest({ + appId, + roleId, + universalIdentifiers, + checksumVersion: 'v1', + }), + ); + + // oxlint-disable-next-line no-console + console.log( + `[install-perf][test] ===== N=${count} : SECOND SYNC (update ${count} functions, checksum v2) =====`, + ); + + const updateMs = await timeSync( + `N=${count} update sync`, + buildManifest({ + appId, + roleId, + universalIdentifiers, + checksumVersion: 'v2', + }), + ); + + // oxlint-disable-next-line no-console + console.log( + `[install-perf][test] ===== N=${count} SUMMARY: create=${createMs.toFixed(1)}ms update=${updateMs.toFixed(1)}ms =====`, + ); + } finally { + await cleanupApplicationAndAppRegistration({ + applicationUniversalIdentifier: appId, + }); + } + }, + 120000, + ); +});