chore(twenty-server): temporary instrumentation for app-install 504 (#21365)

## 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.
2026-06-09 15:57:25 +02:00
parent 7606dd75a8
commit fcaf2b4d9b
5 changed files with 309 additions and 5 deletions
@@ -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(
@@ -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<string, number> = {};
+
+    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,
@@ -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,
+      );
    }
  }

@@ -167,6 +167,36 @@ export class WorkspaceMigrationRunnerService {
    );
  }

+  // TODO(install-perf): temporary, remove. Snapshots blocking DB sessions on a fresh connection.
+  private async logBlockingDbActivity(): Promise<void> {
+    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');
@@ -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<number> => {
+  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,
+  );
+});