fcaf2b4d9b
## 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.
152 lines
4.8 KiB
TypeScript
152 lines
4.8 KiB
TypeScript
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,
|
|
);
|
|
});
|