mirror of
https://github.com/Unleash/unleash.git
synced 2025-09-24 17:51:14 +02:00
chore: startup investigation
This commit is contained in:
Gastón Fournier
parent
c7cb5465ff
commit
c76e67720a
@ -40,7 +40,7 @@
|
||||
"build:frontend:if-needed": "./scripts/build-frontend-if-needed.sh",
|
||||
"build": "yarn run clean && concurrently \"yarn:copy-templates\" \"yarn:build:frontend\" \"yarn:build:backend\"",
|
||||
"dev:vite": "TZ=UTC NODE_ENV=development vite-node src/server-dev.ts",
|
||||
"dev:backend": "TZ=UTC NODE_ENV=${NODE_ENV:-development} tsc-watch --onEmit \"copyfiles -u 2 src/migrations/package.json dist/migrations\" --onSuccess \"node dist/server-dev.js\"",
|
||||
"dev:backend": "TZ=UTC NODE_ENV=${NODE_ENV:-development} NODE_OPTIONS=\"--enable-source-maps --import file:///${PWD}/dist/startup-profiler.js\" tsc-watch --onEmit \"copyfiles -u 2 src/migrations/package.json dist/migrations\" --onSuccess \"node dist/server-dev.js\"",
|
||||
"dev:frontend": "wait-on tcp:4242 && yarn --cwd ./frontend run dev",
|
||||
"dev:frontend:cloud": "UNLEASH_BASE_PATH=/demo/ yarn run dev:frontend",
|
||||
"dev": "concurrently \"yarn:dev:backend\" \"yarn:dev:frontend\"",
|
||||
|
||||
669
src/startup-profiler.ts
Normal file
669
src/startup-profiler.ts
Normal file
@ -0,0 +1,669 @@
|
||||
// ESM Startup Profiler (TypeScript)
|
||||
// Run with: NODE_OPTIONS="--import file://$PWD/dist/profiling/startup-profiler.mjs" node dist/server.js
|
||||
import fs from 'node:fs';
|
||||
import path from 'node:path';
|
||||
import http from 'node:http';
|
||||
import https from 'node:https';
|
||||
import { performance } from 'node:perf_hooks';
|
||||
import async_hooks from 'node:async_hooks';
|
||||
import inspector from 'node:inspector';
|
||||
import Module from 'node:module';
|
||||
|
||||
// -------------------- config --------------------
|
||||
const THRESHOLD_MS = Number(process.env.STARTUP_PROFILER_SLOW ?? 15);
|
||||
const REPORT_TXT = path.resolve(
|
||||
process.cwd(),
|
||||
process.env.STARTUP_PROFILER_TXT ?? 'startup-report.txt',
|
||||
);
|
||||
const TRACE_JSON = path.resolve(
|
||||
process.cwd(),
|
||||
process.env.STARTUP_PROFILER_TRACE ?? 'startup-trace.json',
|
||||
);
|
||||
const CPU_PROFILE = path.resolve(
|
||||
process.cwd(),
|
||||
process.env.STARTUP_CPU_PROFILE ?? 'startup-cpu.cpuprofile',
|
||||
);
|
||||
const STACK_FRAMES = Number(process.env.STARTUP_STACK_FRAMES ?? 6);
|
||||
// Additional tuning knobs
|
||||
const MODULE_LOAD_THRESHOLD = Number(process.env.STARTUP_MODULE_THRESHOLD ?? 5); // ms for reporting slow module loads
|
||||
const ENABLE_PROMISE_STACK_GROUPING = Boolean(
|
||||
(process.env.STARTUP_GROUP_PROMISE_STACK ?? '1') !== '0',
|
||||
);
|
||||
const MAX_PROMISE_STACKS = Number(process.env.STARTUP_MAX_PROMISE_STACKS ?? 30);
|
||||
const CAPTURE_MODULE_STACK = Boolean(
|
||||
(process.env.STARTUP_MODULE_STACK ?? '1') !== '0',
|
||||
);
|
||||
const MIGRATIONS_KEYWORD =
|
||||
process.env.STARTUP_MIGRATIONS_KEYWORD ?? '/migrations';
|
||||
|
||||
// -------------------- trace helpers (Chrome trace) --------------------
|
||||
Error.stackTraceLimit = 50;
|
||||
type TraceEvt =
|
||||
| {
|
||||
name: string;
|
||||
cat: string;
|
||||
ph: 'B' | 'E';
|
||||
ts: number;
|
||||
pid: number;
|
||||
tid: number;
|
||||
args?: Record<string, unknown>;
|
||||
}
|
||||
| {
|
||||
name: string;
|
||||
cat: string;
|
||||
ph: 'i';
|
||||
s: 't';
|
||||
ts: number;
|
||||
pid: number;
|
||||
tid: number;
|
||||
args?: Record<string, unknown>;
|
||||
};
|
||||
|
||||
const traceEvents: TraceEvt[] = [];
|
||||
function tsNowUs() {
|
||||
return (performance.timeOrigin + performance.now()) * 1000;
|
||||
}
|
||||
function traceBegin(
|
||||
name: string,
|
||||
cat = 'startup',
|
||||
args: Record<string, unknown> = {},
|
||||
) {
|
||||
traceEvents.push({
|
||||
name,
|
||||
cat,
|
||||
ph: 'B',
|
||||
ts: tsNowUs(),
|
||||
pid: process.pid,
|
||||
tid: 0,
|
||||
args,
|
||||
});
|
||||
}
|
||||
function traceEnd(
|
||||
name: string,
|
||||
cat = 'startup',
|
||||
args: Record<string, unknown> = {},
|
||||
) {
|
||||
traceEvents.push({
|
||||
name,
|
||||
cat,
|
||||
ph: 'E',
|
||||
ts: tsNowUs(),
|
||||
pid: process.pid,
|
||||
tid: 0,
|
||||
args,
|
||||
});
|
||||
}
|
||||
function traceInstant(
|
||||
name: string,
|
||||
cat = 'startup',
|
||||
args: Record<string, unknown> = {},
|
||||
) {
|
||||
traceEvents.push({
|
||||
name,
|
||||
cat,
|
||||
ph: 'i',
|
||||
s: 't',
|
||||
ts: tsNowUs(),
|
||||
pid: process.pid,
|
||||
tid: 0,
|
||||
args,
|
||||
});
|
||||
}
|
||||
traceInstant('process_start');
|
||||
|
||||
// -------------------- label context --------------------
|
||||
// We attribute async work to *who scheduled it* via a label carried on the async tree.
|
||||
type Ctx = { label: string; stack?: string[] };
|
||||
const ctxLabel = new Map<number, Ctx>(); // executionAsyncId -> ctx
|
||||
const parentOf = new Map<number, number>(); // child asyncId -> parent asyncId
|
||||
|
||||
function cleanStack(max = STACK_FRAMES): string[] | undefined {
|
||||
const raw = (new Error().stack ?? '').split('\n').slice(2);
|
||||
const user = raw
|
||||
.map((l) => l.trim())
|
||||
.filter(
|
||||
(l) =>
|
||||
!/(node:internal|\/async_hooks|\/perf_hooks|\/inspector|startup-profiler)/.test(
|
||||
l,
|
||||
),
|
||||
)
|
||||
.map((l) => l.replace(`${process.cwd()}/`, ''))
|
||||
.slice(0, max);
|
||||
return user.length ? user : undefined;
|
||||
}
|
||||
|
||||
function stackSignature(stack?: string[]): string | undefined {
|
||||
if (!stack || !stack.length) return undefined;
|
||||
return stack
|
||||
.slice(0, 4)
|
||||
.map((f) => f.replace(/:\d+:\d+\)?$/, ')').replace(/\s+/g, ' '))
|
||||
.join(' | ');
|
||||
}
|
||||
|
||||
function setLabelForCurrent(label: string) {
|
||||
const id = async_hooks.executionAsyncId();
|
||||
ctxLabel.set(id, { label, stack: cleanStack() });
|
||||
}
|
||||
|
||||
function resolveLabelFrom(triggerId?: number): Ctx | undefined {
|
||||
let t = triggerId;
|
||||
let hops = 0;
|
||||
while (typeof t === 'number' && hops < 100) {
|
||||
const ctx = ctxLabel.get(t);
|
||||
if (ctx) return ctx;
|
||||
t = parentOf.get(t);
|
||||
hops++;
|
||||
}
|
||||
return undefined;
|
||||
}
|
||||
|
||||
// -------------------- wrap listen() to mark startup end --------------------
|
||||
const START = performance.now();
|
||||
let END: number | null = null;
|
||||
let listenTarget: {
|
||||
proto: 'http' | 'https';
|
||||
address: string | null;
|
||||
port: number | null;
|
||||
} | null = null;
|
||||
|
||||
function wrapListen(
|
||||
proto: 'http' | 'https',
|
||||
Cls: typeof http.Server | typeof https.Server,
|
||||
) {
|
||||
const orig = (Cls as any).prototype.listen as http.Server['listen'];
|
||||
(Cls as any).prototype.listen = function (...args: any[]) {
|
||||
const res = orig.apply(this, args as any);
|
||||
const onListening = () => {
|
||||
if (END) return;
|
||||
END = performance.now();
|
||||
try {
|
||||
this.removeListener('listening', onListening);
|
||||
} catch {}
|
||||
const addr = this.address() as any;
|
||||
listenTarget = {
|
||||
proto,
|
||||
address:
|
||||
typeof addr === 'string' ? addr : (addr?.address ?? null),
|
||||
port: typeof addr === 'string' ? null : (addr?.port ?? null),
|
||||
};
|
||||
finalize();
|
||||
};
|
||||
this.on('listening', onListening);
|
||||
traceInstant(`listen_called:${proto}`, 'listen', {
|
||||
args: summarizeListenArgs(args),
|
||||
});
|
||||
return res;
|
||||
};
|
||||
}
|
||||
function summarizeListenArgs(args: any[]) {
|
||||
const out: Record<string, unknown> = {};
|
||||
for (const a of args) {
|
||||
if (typeof a === 'number') out.port = a;
|
||||
else if (typeof a === 'string') out.hostOrPath = a;
|
||||
}
|
||||
return out;
|
||||
}
|
||||
wrapListen('http', http.Server);
|
||||
wrapListen('https', https.Server);
|
||||
|
||||
// Safety net when no server listens (CLIs, failed boots)
|
||||
process.on('beforeExit', () => {
|
||||
if (!END) {
|
||||
END = performance.now();
|
||||
finalize(true);
|
||||
}
|
||||
});
|
||||
|
||||
// -------------------- patch common async APIs (so we can label) --------------------
|
||||
const g: any = globalThis;
|
||||
|
||||
// fetch (undici)
|
||||
if (typeof g.fetch === 'function') {
|
||||
const origFetch = g.fetch.bind(g);
|
||||
g.fetch = async (...args: any[]) => {
|
||||
const url =
|
||||
typeof args[0] === 'string' ? args[0] : (args[0]?.url ?? '');
|
||||
setLabelForCurrent(`fetch ${url}`);
|
||||
traceBegin(`fetch:${url}`, 'net');
|
||||
try {
|
||||
return await origFetch(...args);
|
||||
} finally {
|
||||
traceEnd(`fetch:${url}`, 'net');
|
||||
}
|
||||
};
|
||||
}
|
||||
|
||||
// timers
|
||||
for (const name of ['setTimeout', 'setImmediate'] as const) {
|
||||
const orig = (g as any)[name].bind(g);
|
||||
(g as any)[name] = (fn: Function, ...rest: any[]) => {
|
||||
setLabelForCurrent(name);
|
||||
return orig(fn, ...rest);
|
||||
};
|
||||
}
|
||||
|
||||
// (Optional) add wrappers for SDK init you suspect:
|
||||
// e.g. before prisma.connect() / otel.start() / redis.connect(), call setLabelForCurrent('prisma.connect').
|
||||
|
||||
// -------------------- async_hooks: timing + label inheritance --------------------
|
||||
type Rec = { type: string; start: number; ctx?: Ctx };
|
||||
const asyncMap = new Map<number, Rec>();
|
||||
|
||||
const metrics = {
|
||||
async: { total: 0, time: 0, byType: new Map<string, number>() },
|
||||
};
|
||||
const slow: Array<{
|
||||
type: string;
|
||||
ms: number;
|
||||
id: number;
|
||||
label?: string;
|
||||
stack?: string[];
|
||||
}> = [];
|
||||
|
||||
// Promise stack aggregation
|
||||
interface PromiseStackAgg {
|
||||
time: number;
|
||||
count: number;
|
||||
stack?: string[];
|
||||
label?: string;
|
||||
}
|
||||
const promiseStacks = new Map<string, PromiseStackAgg>();
|
||||
|
||||
// Module load timing records
|
||||
interface ModuleLoadRec {
|
||||
request: string;
|
||||
parent?: string;
|
||||
ms: number;
|
||||
stack?: string[];
|
||||
}
|
||||
const moduleLoads: ModuleLoadRec[] = [];
|
||||
|
||||
const _load = (Module as any)._load as (
|
||||
req: string,
|
||||
parent: any,
|
||||
isMain: boolean,
|
||||
) => any;
|
||||
(Module as any)._load = function (req: string, parent: any, isMain: boolean) {
|
||||
const modStart = performance.now();
|
||||
const stack = CAPTURE_MODULE_STACK ? cleanStack(6) : undefined;
|
||||
// biome-ignore lint/style/noArguments: preserve args
|
||||
const mod = _load.apply(this, arguments as any);
|
||||
const dt = performance.now() - modStart;
|
||||
if (!END && dt >= MODULE_LOAD_THRESHOLD) {
|
||||
moduleLoads.push({
|
||||
request: req,
|
||||
parent: parent?.filename,
|
||||
ms: dt,
|
||||
stack,
|
||||
});
|
||||
traceInstant('module_load', 'module', { req, ms: dt });
|
||||
}
|
||||
|
||||
if (req === 'db-migrate' && mod && !(mod as any).__startupPatched) {
|
||||
(mod as any).__startupPatched = true;
|
||||
const origGetInstance = (mod as any).getInstance?.bind(mod);
|
||||
if (origGetInstance) {
|
||||
(mod as any).getInstance = (...args: any[]) => {
|
||||
const inst = origGetInstance(...args);
|
||||
for (const m of [
|
||||
'up',
|
||||
'down',
|
||||
'reset',
|
||||
'sync',
|
||||
'connect',
|
||||
] as const) {
|
||||
const fn = (inst as any)[m];
|
||||
if (typeof fn === 'function') {
|
||||
(inst as any)[m] = async function (...fa: any[]) {
|
||||
setLabelForCurrent(`db-migrate ${m}`);
|
||||
traceBegin(`db-migrate:${m}`, 'db');
|
||||
try {
|
||||
return await fn.apply(this, fa);
|
||||
} finally {
|
||||
traceEnd(`db-migrate:${m}`, 'db');
|
||||
}
|
||||
};
|
||||
}
|
||||
}
|
||||
return inst;
|
||||
};
|
||||
}
|
||||
}
|
||||
|
||||
if (req === 'pg' && mod && !(mod as any).__startupPatched) {
|
||||
(mod as any).__startupPatched = true;
|
||||
try {
|
||||
const { Client, Pool } = mod as any;
|
||||
if (Client?.prototype?.connect) {
|
||||
const orig = Client.prototype.connect;
|
||||
Client.prototype.connect = function (...fa: any[]) {
|
||||
setLabelForCurrent('pg.connect');
|
||||
return orig.apply(this, fa);
|
||||
};
|
||||
}
|
||||
if (Pool?.prototype?.connect) {
|
||||
const origP = Pool.prototype.connect;
|
||||
Pool.prototype.connect = function (...fa: any[]) {
|
||||
setLabelForCurrent('pg.pool.connect');
|
||||
return origP.apply(this, fa);
|
||||
};
|
||||
}
|
||||
} catch {}
|
||||
}
|
||||
|
||||
return mod;
|
||||
};
|
||||
|
||||
// Patch CJS compilation to surface big parse/transform cost
|
||||
const exts = Module as any;
|
||||
if (exts?._extensions) {
|
||||
for (const [ext, loader] of Object.entries<any>(exts._extensions)) {
|
||||
if (typeof loader !== 'function') continue;
|
||||
if ((loader as any).__startupPatched) continue;
|
||||
exts._extensions[ext] = (m: any, filename: string) => {
|
||||
const start = performance.now();
|
||||
try {
|
||||
return loader(m, filename);
|
||||
} finally {
|
||||
const dt2 = performance.now() - start;
|
||||
if (!END && dt2 >= MODULE_LOAD_THRESHOLD) {
|
||||
moduleLoads.push({
|
||||
request: filename.replace(`${process.cwd()}/`, ''),
|
||||
parent: 'compile',
|
||||
ms: dt2,
|
||||
stack: CAPTURE_MODULE_STACK ? cleanStack(4) : undefined,
|
||||
});
|
||||
traceInstant('module_compile', 'module', {
|
||||
file: filename,
|
||||
ms: dt2,
|
||||
});
|
||||
}
|
||||
}
|
||||
};
|
||||
(exts._extensions[ext] as any).__startupPatched = true;
|
||||
}
|
||||
}
|
||||
|
||||
// Targeted fs instrumentation (especially for large migrations directory scans)
|
||||
function markIfMigrations(op: string, target: any) {
|
||||
if (typeof target === 'string' && target.includes(MIGRATIONS_KEYWORD)) {
|
||||
setLabelForCurrent(`${op}:${path.basename(target)}`);
|
||||
}
|
||||
}
|
||||
try {
|
||||
const origReaddir = fs.readdir.bind(fs);
|
||||
fs.readdir = ((...args: Parameters<typeof fs.readdir>) => {
|
||||
markIfMigrations('fs.readdir', args[0]);
|
||||
return (origReaddir as any)(...(args as any));
|
||||
}) as any;
|
||||
const origReadFile = fs.readFile.bind(fs);
|
||||
fs.readFile = ((...args: Parameters<typeof fs.readFile>) => {
|
||||
markIfMigrations('fs.readFile', args[0]);
|
||||
return (origReadFile as any)(...(args as any));
|
||||
}) as any;
|
||||
if (fs.promises) {
|
||||
const p = fs.promises as any;
|
||||
if (p.readdir) {
|
||||
const orig = p.readdir.bind(p);
|
||||
p.readdir = async (...args: any[]) => {
|
||||
markIfMigrations('fsp.readdir', args[0]);
|
||||
return orig(...args);
|
||||
};
|
||||
}
|
||||
if (p.readFile) {
|
||||
const orig = p.readFile.bind(p);
|
||||
p.readFile = async (...args: any[]) => {
|
||||
markIfMigrations('fsp.readFile', args[0]);
|
||||
return orig(...args);
|
||||
};
|
||||
}
|
||||
}
|
||||
} catch {}
|
||||
|
||||
const ahook = async_hooks.createHook({
|
||||
init(asyncId, type, triggerAsyncId) {
|
||||
parentOf.set(asyncId, triggerAsyncId);
|
||||
const rec: Rec = { type, start: performance.now() };
|
||||
const inherited = resolveLabelFrom(triggerAsyncId);
|
||||
if (inherited) {
|
||||
rec.ctx = inherited;
|
||||
} else if (type === 'PROMISE') {
|
||||
// fallback: capture a small user stack so "Sample of slow ops" isn't empty
|
||||
rec.ctx = { label: 'promise', stack: cleanStack(12) };
|
||||
}
|
||||
asyncMap.set(asyncId, rec);
|
||||
traceBegin(`async:${type}:${asyncId}`, 'async', {
|
||||
type,
|
||||
label: inherited?.label,
|
||||
});
|
||||
},
|
||||
destroy(asyncId) {
|
||||
const rec = asyncMap.get(asyncId);
|
||||
if (!rec) return;
|
||||
asyncMap.delete(asyncId);
|
||||
const dt = performance.now() - rec.start;
|
||||
metrics.async.total++;
|
||||
metrics.async.time += dt;
|
||||
metrics.async.byType.set(
|
||||
rec.type,
|
||||
(metrics.async.byType.get(rec.type) ?? 0) + dt,
|
||||
);
|
||||
const label = rec.ctx?.label;
|
||||
const stack = rec.ctx?.stack;
|
||||
traceEnd(`async:${rec.type}:${asyncId}`, 'async', {
|
||||
dur: dt,
|
||||
label,
|
||||
stack,
|
||||
});
|
||||
if (!END && dt >= THRESHOLD_MS) {
|
||||
slow.push({ type: rec.type, ms: dt, id: asyncId, label, stack });
|
||||
if (ENABLE_PROMISE_STACK_GROUPING && rec.type === 'PROMISE') {
|
||||
const sig = stackSignature(stack);
|
||||
if (sig) {
|
||||
const agg = promiseStacks.get(sig) || {
|
||||
time: 0,
|
||||
count: 0,
|
||||
stack,
|
||||
label,
|
||||
};
|
||||
agg.time += dt;
|
||||
agg.count += 1;
|
||||
if (!agg.stack && stack) agg.stack = stack;
|
||||
promiseStacks.set(sig, agg);
|
||||
}
|
||||
}
|
||||
}
|
||||
},
|
||||
});
|
||||
ahook.enable();
|
||||
|
||||
// -------------------- CPU profile during startup --------------------
|
||||
let session: inspector.Session | null = null;
|
||||
try {
|
||||
session = new inspector.Session();
|
||||
session.connect();
|
||||
await new Promise<void>((r) =>
|
||||
session!.post('Profiler.enable', () =>
|
||||
session!.post('Profiler.start', () => r()),
|
||||
),
|
||||
);
|
||||
} catch {
|
||||
// ignore if inspector unavailable
|
||||
}
|
||||
|
||||
// -------------------- finalize & reporting --------------------
|
||||
function pct(n: number) {
|
||||
return `${((n / Math.max(1, END! - START)) * 100).toFixed(1)}%`;
|
||||
}
|
||||
|
||||
function writeCpuProfile() {
|
||||
if (!session) return;
|
||||
try {
|
||||
session.post('Profiler.stop', (_err: any, payload: any) => {
|
||||
try {
|
||||
fs.writeFileSync(
|
||||
CPU_PROFILE,
|
||||
JSON.stringify(payload?.profile ?? payload ?? {}),
|
||||
);
|
||||
} catch {}
|
||||
try {
|
||||
session?.disconnect();
|
||||
} catch {}
|
||||
session = null;
|
||||
});
|
||||
} catch {
|
||||
/* ignore */
|
||||
}
|
||||
}
|
||||
|
||||
function finalize(noListen = false) {
|
||||
try {
|
||||
ahook.disable();
|
||||
} catch {}
|
||||
traceInstant('startup_end', 'milestone', { noListen });
|
||||
const total = END! - START;
|
||||
|
||||
// Aggregate by label for readability
|
||||
const byLabel = new Map<
|
||||
string,
|
||||
{ count: number; time: number; sampleStack?: string[] }
|
||||
>();
|
||||
for (const s of slow) {
|
||||
const key = s.label ?? s.type;
|
||||
const agg = byLabel.get(key) ?? {
|
||||
count: 0,
|
||||
time: 0,
|
||||
sampleStack: s.stack,
|
||||
};
|
||||
agg.count++;
|
||||
agg.time += s.ms;
|
||||
if (!agg.sampleStack && s.stack) agg.sampleStack = s.stack;
|
||||
byLabel.set(key, agg);
|
||||
}
|
||||
|
||||
const lines: string[] = [];
|
||||
lines.push(`Node ${process.version} | PID ${process.pid}`);
|
||||
lines.push(`Startup window: ${total.toFixed(2)} ms`);
|
||||
if (listenTarget && !noListen) {
|
||||
lines.push(
|
||||
`First server listening: ${listenTarget.proto}://${listenTarget.address ?? '0.0.0.0'}:${listenTarget.port ?? ''}`,
|
||||
);
|
||||
} else {
|
||||
lines.push(
|
||||
`No server "listening" detected; dumping until process idle.`,
|
||||
);
|
||||
}
|
||||
lines.push('');
|
||||
|
||||
lines.push(`= Async operations before listen =`);
|
||||
lines.push(
|
||||
` ops: ${metrics.async.total} | time (sum): ${metrics.async.time.toFixed(2)} ms`,
|
||||
);
|
||||
if (metrics.async.byType.size) {
|
||||
lines.push(` by type:`);
|
||||
for (const [t, ms] of [...metrics.async.byType.entries()].sort(
|
||||
(a, b) => b[1] - a[1],
|
||||
)) {
|
||||
lines.push(` ${t.padEnd(14)} ${ms.toFixed(2)} ms (${pct(ms)})`);
|
||||
}
|
||||
}
|
||||
|
||||
lines.push('');
|
||||
lines.push(`= Top slow async groups (by label) =`);
|
||||
if (byLabel.size === 0) {
|
||||
lines.push(' (none over threshold)');
|
||||
} else {
|
||||
for (const [label, v] of [...byLabel.entries()]
|
||||
.sort((a, b) => b[1].time - a[1].time)
|
||||
.slice(0, 30)) {
|
||||
lines.push(
|
||||
` ${label}: ${v.time.toFixed(2)} ms across ${v.count} ops`,
|
||||
);
|
||||
if (v.sampleStack)
|
||||
for (const f of v.sampleStack.slice(0, 5))
|
||||
lines.push(` at ${f}`);
|
||||
}
|
||||
}
|
||||
|
||||
if (slow.length) {
|
||||
lines.push('');
|
||||
lines.push(`= Sample of slow ops (>${THRESHOLD_MS} ms) =`);
|
||||
for (const s of slow.sort((a, b) => b.ms - a.ms).slice(0, 50)) {
|
||||
lines.push(
|
||||
` ${s.ms.toFixed(2)} ms ${s.type}${s.label ? ` [${s.label}]` : ''} (id ${s.id})`,
|
||||
);
|
||||
if (s.stack?.length)
|
||||
for (const f of s.stack.slice(0, 4))
|
||||
lines.push(` at ${f}`);
|
||||
}
|
||||
}
|
||||
|
||||
if (ENABLE_PROMISE_STACK_GROUPING && promiseStacks.size) {
|
||||
lines.push('');
|
||||
lines.push('= Top PROMISE stacks (aggregated) =');
|
||||
for (const [sig, agg] of [...promiseStacks.entries()]
|
||||
.sort((a, b) => b[1].time - a[1].time)
|
||||
.slice(0, MAX_PROMISE_STACKS)) {
|
||||
lines.push(
|
||||
` ${agg.time.toFixed(2)} ms across ${agg.count} promises :: ${sig}${agg.label ? ` [label:${agg.label}]` : ''}`,
|
||||
);
|
||||
if (agg.stack) {
|
||||
for (const f of agg.stack.slice(0, 6))
|
||||
lines.push(` at ${f}`);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
if (moduleLoads.length) {
|
||||
lines.push('');
|
||||
lines.push('= Slow module loads / compilations =');
|
||||
const byReq = new Map<
|
||||
string,
|
||||
{ time: number; count: number; stack?: string[] }
|
||||
>();
|
||||
for (const m of moduleLoads) {
|
||||
const key = m.request;
|
||||
const agg = byReq.get(key) || {
|
||||
time: 0,
|
||||
count: 0,
|
||||
stack: m.stack,
|
||||
};
|
||||
agg.time += m.ms;
|
||||
agg.count += 1;
|
||||
if (!agg.stack && m.stack) agg.stack = m.stack;
|
||||
byReq.set(key, agg);
|
||||
}
|
||||
for (const [req, agg] of [...byReq.entries()]
|
||||
.sort((a, b) => b[1].time - a[1].time)
|
||||
.slice(0, 40)) {
|
||||
lines.push(
|
||||
` ${agg.time.toFixed(2)} ms across ${agg.count} load(s) :: ${req}`,
|
||||
);
|
||||
if (agg.stack) {
|
||||
for (const f of agg.stack.slice(0, 4))
|
||||
lines.push(` at ${f}`);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
lines.push('');
|
||||
lines.push(
|
||||
`Tips: move DB connect/migrations after listen(); lazy-load heavy routes; avoid sync FS; defer remote config/secret fetches; inspect "Slow module loads" and "Top PROMISE stacks" (tune with STARTUP_* env vars).`,
|
||||
);
|
||||
|
||||
try {
|
||||
fs.writeFileSync(REPORT_TXT, `${lines.join('\n')}\n`, 'utf8');
|
||||
} catch {}
|
||||
try {
|
||||
fs.writeFileSync(
|
||||
TRACE_JSON,
|
||||
JSON.stringify({ traceEvents }, null, 2),
|
||||
'utf8',
|
||||
);
|
||||
} catch {}
|
||||
writeCpuProfile();
|
||||
|
||||
console.error(
|
||||
`[startup-profiler] ${total.toFixed(2)} ms before first "listening". Report: ${REPORT_TXT} | Trace: ${TRACE_JSON} | CPU: ${CPU_PROFILE}`,
|
||||
);
|
||||
}
|
||||
1
startup-cpu.cpuprofile
Normal file
1
startup-cpu.cpuprofile
Normal file
File diff suppressed because one or more lines are too long
402
startup-report.txt
Normal file
402
startup-report.txt
Normal file
@ -0,0 +1,402 @@
|
||||
Node v22.17.1 | PID 2141941
|
||||
Startup window: 2934.39 ms
|
||||
First server listening: http://:::4242
|
||||
|
||||
= Async operations before listen =
|
||||
ops: 43218 | time (sum): 14113527.21 ms
|
||||
by type:
|
||||
PROMISE 13306289.12 ms (453460.8%)
|
||||
FILEHANDLECLOSEREQ 289939.98 ms (9880.8%)
|
||||
FSREQPROMISE 274105.20 ms (9341.1%)
|
||||
FILEHANDLE 242402.28 ms (8260.8%)
|
||||
TickObject 234.01 ms (8.0%)
|
||||
RANDOMBYTESREQUEST 221.09 ms (7.5%)
|
||||
Timeout 218.94 ms (7.5%)
|
||||
Immediate 45.68 ms (1.6%)
|
||||
TCPWRAP 36.86 ms (1.3%)
|
||||
SHUTDOWNWRAP 15.46 ms (0.5%)
|
||||
GETADDRINFOREQWRAP 11.81 ms (0.4%)
|
||||
TCPCONNECTWRAP 4.23 ms (0.1%)
|
||||
FSREQCALLBACK 2.54 ms (0.1%)
|
||||
|
||||
= Top slow async groups (by label) =
|
||||
promise: 13295053.76 ms across 38216 ops
|
||||
at at new Promise (<anonymous>)
|
||||
FILEHANDLECLOSEREQ: 289934.19 ms across 862 ops
|
||||
FSREQPROMISE: 271859.34 ms across 2349 ops
|
||||
FILEHANDLE: 242394.26 ms across 354 ops
|
||||
setImmediate: 368.57 ms across 10 ops
|
||||
at at Async.schedule [as _schedule] (node_modules/bluebird/js/release/schedule.js:12:53)
|
||||
at at Async._queueTick (node_modules/bluebird/js/release/async.js:111:14)
|
||||
at at Async.AsyncInvoke [as invoke] (node_modules/bluebird/js/release/async.js:71:10)
|
||||
at at Promise._then (node_modules/bluebird/js/release/promise.js:290:15)
|
||||
at at Promise.then (node_modules/bluebird/js/release/promise.js:154:17)
|
||||
RANDOMBYTESREQUEST: 221.09 ms across 1 ops
|
||||
setTimeout: 166.54 ms across 6 ops
|
||||
at at Client._connect (node_modules/pg/lib/client.js:104:38)
|
||||
at at Client.connect (node_modules/pg/lib/client.js:166:12)
|
||||
at at exports.connect (node_modules/db-migrate-pg/index.js:775:6)
|
||||
at at connect (node_modules/db-migrate/lib/driver/index.js:93:12)
|
||||
at at exports.connect (node_modules/db-migrate/lib/driver/index.js:134:5)
|
||||
pg.connect: 59.72 ms across 2 ops
|
||||
at at Client_PG._acquireOnlyConnection (node_modules/knex/lib/dialects/postgres/index.js:91:23)
|
||||
at at Client_PG.acquireRawConnection (node_modules/knex/lib/dialects/postgres/index.js:99:17)
|
||||
at at create (node_modules/knex/lib/client.js:262:39)
|
||||
TickObject: 53.63 ms across 1 ops
|
||||
|
||||
= Sample of slow ops (>15 ms) =
|
||||
1134.35 ms PROMISE [promise] (id 63855)
|
||||
1134.21 ms PROMISE [promise] (id 63859)
|
||||
at at new Promise (<anonymous>)
|
||||
1134.08 ms PROMISE [promise] (id 63867)
|
||||
at at Promise.then (<anonymous>)
|
||||
at at new Promise (<anonymous>)
|
||||
1134.06 ms PROMISE [promise] (id 63868)
|
||||
1134.01 ms PROMISE [promise] (id 63870)
|
||||
1133.99 ms PROMISE [promise] (id 63871)
|
||||
1133.97 ms PROMISE [promise] (id 63872)
|
||||
1133.95 ms PROMISE [promise] (id 63873)
|
||||
1133.93 ms PROMISE [promise] (id 63874)
|
||||
1133.90 ms PROMISE [promise] (id 63875)
|
||||
1133.87 ms PROMISE [promise] (id 63876)
|
||||
1133.83 ms PROMISE [promise] (id 63878)
|
||||
at at Promise.then (<anonymous>)
|
||||
1133.81 ms PROMISE [promise] (id 63879)
|
||||
1133.78 ms PROMISE [promise] (id 63880)
|
||||
1133.76 ms PROMISE [promise] (id 63881)
|
||||
1133.74 ms PROMISE [promise] (id 63882)
|
||||
1133.73 ms PROMISE [promise] (id 63883)
|
||||
1133.68 ms PROMISE [promise] (id 63885)
|
||||
1133.67 ms PROMISE [promise] (id 63886)
|
||||
at at Promise.then (<anonymous>)
|
||||
1133.64 ms PROMISE [promise] (id 63887)
|
||||
at at Promise.then (<anonymous>)
|
||||
1133.63 ms PROMISE [promise] (id 63888)
|
||||
at at Promise.then (<anonymous>)
|
||||
1133.52 ms PROMISE [promise] (id 63896)
|
||||
at at Promise.then (<anonymous>)
|
||||
1128.85 ms PROMISE [promise] (id 64070)
|
||||
at at new Promise (<anonymous>)
|
||||
1128.51 ms PROMISE [promise] (id 64091)
|
||||
at at new Promise (<anonymous>)
|
||||
1128.50 ms PROMISE [promise] (id 64092)
|
||||
at at new Promise (<anonymous>)
|
||||
1128.48 ms PROMISE [promise] (id 64093)
|
||||
at at Promise.then (<anonymous>)
|
||||
at at new Promise (<anonymous>)
|
||||
1126.44 ms PROMISE [promise] (id 64217)
|
||||
at at Promise.then (<anonymous>)
|
||||
1125.06 ms PROMISE [promise] (id 64266)
|
||||
at at Promise.then (<anonymous>)
|
||||
1124.97 ms PROMISE [promise] (id 64270)
|
||||
at at Promise.then (<anonymous>)
|
||||
1124.89 ms PROMISE [promise] (id 64274)
|
||||
at at Promise.then (<anonymous>)
|
||||
1124.80 ms PROMISE [promise] (id 64278)
|
||||
at at Promise.then (<anonymous>)
|
||||
1124.72 ms PROMISE [promise] (id 64282)
|
||||
at at Promise.then (<anonymous>)
|
||||
1124.65 ms PROMISE [promise] (id 64286)
|
||||
at at Promise.then (<anonymous>)
|
||||
1124.57 ms PROMISE [promise] (id 64290)
|
||||
at at Promise.then (<anonymous>)
|
||||
1124.50 ms PROMISE [promise] (id 64294)
|
||||
at at Promise.then (<anonymous>)
|
||||
1124.48 ms PROMISE [promise] (id 64295)
|
||||
1124.42 ms PROMISE [promise] (id 64298)
|
||||
at at Promise.then (<anonymous>)
|
||||
1124.41 ms PROMISE [promise] (id 64299)
|
||||
at at new Promise (<anonymous>)
|
||||
1124.32 ms PROMISE [promise] (id 64303)
|
||||
at at Promise.then (<anonymous>)
|
||||
at at new Promise (<anonymous>)
|
||||
1124.22 ms PROMISE [promise] (id 64309)
|
||||
1124.17 ms PROMISE [promise] (id 64311)
|
||||
1124.16 ms PROMISE [promise] (id 64312)
|
||||
1124.14 ms PROMISE [promise] (id 64313)
|
||||
1124.12 ms PROMISE [promise] (id 64314)
|
||||
1124.10 ms PROMISE [promise] (id 64315)
|
||||
1124.07 ms PROMISE [promise] (id 64316)
|
||||
1124.04 ms PROMISE [promise] (id 64317)
|
||||
1124.01 ms PROMISE [promise] (id 64319)
|
||||
at at Promise.then (<anonymous>)
|
||||
1123.99 ms PROMISE [promise] (id 64320)
|
||||
1123.96 ms PROMISE [promise] (id 64321)
|
||||
|
||||
= Top PROMISE stacks (aggregated) =
|
||||
3774603.57 ms across 8630 promises :: at Promise.then (<anonymous>) [label:promise]
|
||||
at at Promise.then (<anonymous>)
|
||||
1010836.12 ms across 4832 promises :: at new Promise (<anonymous>) [label:promise]
|
||||
at at new Promise (<anonymous>)
|
||||
1008653.70 ms across 4268 promises :: at Promise.then (<anonymous>) | at new Promise (<anonymous>) [label:promise]
|
||||
at at Promise.then (<anonymous>)
|
||||
at at new Promise (<anonymous>)
|
||||
226733.65 ms across 412 promises :: at new Promise (<anonymous>) | at new Promise (<anonymous>) [label:promise]
|
||||
at at new Promise (<anonymous>)
|
||||
at at new Promise (<anonymous>)
|
||||
226705.14 ms across 412 promises :: at Promise.then (<anonymous>) | at new Promise (<anonymous>) | at new Promise (<anonymous>) [label:promise]
|
||||
at at Promise.then (<anonymous>)
|
||||
at at new Promise (<anonymous>)
|
||||
at at new Promise (<anonymous>)
|
||||
226690.60 ms across 412 promises :: at new Promise (<anonymous>) | at Promise.then (<anonymous>) | at Promise.finally (<anonymous>) | at new Promise (<anonymous>) [label:promise]
|
||||
at at new Promise (<anonymous>)
|
||||
at at Promise.then (<anonymous>)
|
||||
at at Promise.finally (<anonymous>)
|
||||
at at new Promise (<anonymous>)
|
||||
226689.24 ms across 412 promises :: at new Promise (<anonymous>) | at Promise.then (<anonymous>) | at new Promise (<anonymous>) [label:promise]
|
||||
at at new Promise (<anonymous>)
|
||||
at at Promise.then (<anonymous>)
|
||||
at at new Promise (<anonymous>)
|
||||
137085.64 ms across 828 promises :: at new Promise (<anonymous>) | at <anonymous> [label:promise]
|
||||
at at new Promise (<anonymous>)
|
||||
at at <anonymous>
|
||||
137060.61 ms across 828 promises :: at new Promise (<anonymous>) | at Promise.then (<anonymous>) | at <anonymous> [label:promise]
|
||||
at at new Promise (<anonymous>)
|
||||
at at Promise.then (<anonymous>)
|
||||
at at <anonymous>
|
||||
137023.60 ms across 828 promises :: at new Promise (<anonymous>) | at Promise.then (<anonymous>) [label:promise]
|
||||
at at new Promise (<anonymous>)
|
||||
at at Promise.then (<anonymous>)
|
||||
558.43 ms across 1 promises :: at new Promise (<anonymous>) | at <anonymous> (node_modules/ky/source/core/constants.ts) | at <anonymous> (node_modules/ky/source/core/constants.ts) [label:promise]
|
||||
at at new Promise (<anonymous>)
|
||||
at at <anonymous> (node_modules/ky/source/core/constants.ts:14:11)
|
||||
at at <anonymous> (node_modules/ky/source/core/constants.ts:33:3)
|
||||
514.68 ms across 1 promises :: at Function.resolve (<anonymous>) | at Object.<anonymous> (node_modules/lodash/_getTag.js) | at TracingChannel.traceSync (node:diagnostics_channel) | at Object.<anonymous> (node_modules/lodash/_baseClone.js) [label:promise]
|
||||
at at Function.resolve (<anonymous>)
|
||||
at at Object.<anonymous> (node_modules/lodash/_getTag.js:37:32)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/lodash/_baseClone.js:12:14)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/lodash/cloneDeep.js:1:17)
|
||||
494.89 ms across 2 promises :: at new Promise (<anonymous>) | at <anonymous> (node_modules/axios/lib/adapters/fetch.js) | at test (node_modules/axios/lib/adapters/fetch.js) | at Object.<anonymous> (node_modules/axios/lib/adapters/fetch.js) [label:promise]
|
||||
at at new Promise (<anonymous>)
|
||||
at at <anonymous> (node_modules/axios/lib/adapters/fetch.js:32:11)
|
||||
at at test (node_modules/axios/lib/adapters/fetch.js:22:14)
|
||||
at at Object.<anonymous> (node_modules/axios/lib/adapters/fetch.js:28:60)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/@slack/web-api/src/WebClient.ts:8:1)
|
||||
266.54 ms across 5 promises :: at Async.schedule [as _schedule] (node_modules/bluebird/js/release/schedule.js) | at Async._queueTick (node_modules/bluebird/js/release/async.js) | at Async.AsyncInvoke [as invoke] (node_modules/bluebird/js/release/async.js) | at Promise._then (node_modules/bluebird/js/release/promise.js) [label:setImmediate]
|
||||
at at Async.schedule [as _schedule] (node_modules/bluebird/js/release/schedule.js:12:53)
|
||||
at at Async._queueTick (node_modules/bluebird/js/release/async.js:111:14)
|
||||
at at Async.AsyncInvoke [as invoke] (node_modules/bluebird/js/release/async.js:71:10)
|
||||
at at Promise._then (node_modules/bluebird/js/release/promise.js:290:15)
|
||||
at at Promise.then (node_modules/bluebird/js/release/promise.js:154:17)
|
||||
at at module.exports (node_modules/db-migrate/lib/commands/check.js:8:6)
|
||||
227.97 ms across 1 promises :: at Function.resolve (<anonymous>) | at runInContext (node_modules/lodash/lodash.js) | at Object.<anonymous> (node_modules/lodash/lodash.js) | at Object.<anonymous> (node_modules/lodash/lodash.js) [label:promise]
|
||||
at at Function.resolve (<anonymous>)
|
||||
at at runInContext (node_modules/lodash/lodash.js:6113:36)
|
||||
at at Object.<anonymous> (node_modules/lodash/lodash.js:17182:11)
|
||||
at at Object.<anonymous> (node_modules/lodash/lodash.js:17209:3)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
162.49 ms across 1 promises :: at Function.resolve (<anonymous>) | at Object.<anonymous> (node_modules/lodash.isequal/index.js) | at TracingChannel.traceSync (node:diagnostics_channel) | at Object.<anonymous> (node_modules/z-schema/src/SchemaCache.js) [label:promise]
|
||||
at at Function.resolve (<anonymous>)
|
||||
at at Object.<anonymous> (node_modules/lodash.isequal/index.js:1373:32)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/z-schema/src/SchemaCache.js:3:27)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/z-schema/src/ZSchema.js:8:25)
|
||||
101.80 ms across 1 promises :: at requiresMigration (src/migrator.ts) | at start (src/lib/server-impl.ts) | at <anonymous> (src/server-dev.ts) [label:promise]
|
||||
at at requiresMigration (src/migrator.ts:43:40)
|
||||
at at start (src/lib/server-impl.ts:343:23)
|
||||
at at <anonymous> (src/server-dev.ts:8:15)
|
||||
101.65 ms across 1 promises :: at noDatabaseUrl (src/migrator.ts) | at requiresMigration (src/migrator.ts) | at start (src/lib/server-impl.ts) | at <anonymous> (src/server-dev.ts) [label:promise]
|
||||
at at noDatabaseUrl (src/migrator.ts:13:29)
|
||||
at at requiresMigration (src/migrator.ts:46:12)
|
||||
at at start (src/lib/server-impl.ts:343:23)
|
||||
at at <anonymous> (src/server-dev.ts:8:15)
|
||||
101.58 ms across 1 promises :: at <anonymous> (src/migrator.ts) | at noDatabaseUrl (src/migrator.ts) | at requiresMigration (src/migrator.ts) | at start (src/lib/server-impl.ts) [label:promise]
|
||||
at at <anonymous> (src/migrator.ts:46:26)
|
||||
at at noDatabaseUrl (src/migrator.ts:17:20)
|
||||
at at requiresMigration (src/migrator.ts:46:12)
|
||||
at at start (src/lib/server-impl.ts:343:23)
|
||||
at at <anonymous> (src/server-dev.ts:8:15)
|
||||
83.95 ms across 1 promises :: at Function.resolve (<anonymous>) | at Object.<anonymous> (node_modules/lodash.groupby/index.js) | at TracingChannel.traceSync (node:diagnostics_channel) [label:promise]
|
||||
at at Function.resolve (<anonymous>)
|
||||
at at Object.<anonymous> (node_modules/lodash.groupby/index.js:1598:32)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
46.57 ms across 1 promises :: at requiresNode8OrGreater (node_modules/db-migrate/node_modules/yargs/yargs.js) | at Object.<anonymous> (node_modules/db-migrate/node_modules/yargs/yargs.js) | at TracingChannel.traceSync (node:diagnostics_channel) | at Object.<anonymous> (node_modules/db-migrate/node_modules/yargs/index.js) [label:promise]
|
||||
at at requiresNode8OrGreater (node_modules/db-migrate/node_modules/yargs/yargs.js:4:39)
|
||||
at at Object.<anonymous> (node_modules/db-migrate/node_modules/yargs/yargs.js:5:1)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/db-migrate/node_modules/yargs/index.js:5:15)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/db-migrate/lib/commands/set-default-argv.js:1:13)
|
||||
20.07 ms across 1 promises :: at new Promise (<anonymous>) | at Object.getNativePromise (node_modules/bluebird/js/release/util.js) | at Object.<anonymous> (node_modules/bluebird/js/release/schedule.js) | at TracingChannel.traceSync (node:diagnostics_channel) [label:promise]
|
||||
at at new Promise (<anonymous>)
|
||||
at at Object.getNativePromise (node_modules/bluebird/js/release/util.js:328:27)
|
||||
at at Object.<anonymous> (node_modules/bluebird/js/release/schedule.js:7:26)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/bluebird/js/release/async.js:4:16)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
|
||||
= Slow module loads / compilations =
|
||||
278.16 ms across 1 load(s) :: /home/gaston/projects/unleash/node_modules/date-fns/index.js
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
278.07 ms across 1 load(s) :: node_modules/date-fns/index.js
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
136.18 ms across 1 load(s) :: /home/gaston/projects/unleash/node_modules/@wesleytodd/openapi/index.js
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
136.09 ms across 1 load(s) :: node_modules/@wesleytodd/openapi/index.js
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
121.67 ms across 1 load(s) :: /home/gaston/projects/unleash/node_modules/unleash-client/lib/index.js
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
121.57 ms across 1 load(s) :: node_modules/unleash-client/lib/index.js
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
119.88 ms across 1 load(s) :: ./unleash
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/unleash-client/src/index.ts:2:1)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
119.70 ms across 1 load(s) :: node_modules/unleash-client/lib/unleash.js
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/unleash-client/src/index.ts:2:1)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
102.10 ms across 1 load(s) :: /home/gaston/projects/unleash/node_modules/connect-session-knex/dist/index.js
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
102.03 ms across 1 load(s) :: node_modules/connect-session-knex/dist/index.js
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
101.57 ms across 1 load(s) :: knex
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/connect-session-knex/dist/src/index.ts:1:1)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
101.27 ms across 1 load(s) :: node_modules/knex/knex.js
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/connect-session-knex/dist/src/index.ts:1:1)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
101.25 ms across 1 load(s) :: ./lib/index
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/knex/knex.js:8:14)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/connect-session-knex/dist/src/index.ts:1:1)
|
||||
101.12 ms across 1 load(s) :: node_modules/knex/lib/index.js
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/knex/knex.js:8:14)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/connect-session-knex/dist/src/index.ts:1:1)
|
||||
101.08 ms across 1 load(s) :: ./knex-builder/Knex
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/knex/lib/index.js:1:14)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/knex/knex.js:8:14)
|
||||
100.90 ms across 1 load(s) :: node_modules/knex/lib/knex-builder/Knex.js
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/knex/lib/index.js:1:14)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/knex/knex.js:8:14)
|
||||
98.83 ms across 1 load(s) :: ../client
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/knex/lib/knex-builder/Knex.js:1:16)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/knex/lib/index.js:1:14)
|
||||
98.57 ms across 1 load(s) :: node_modules/knex/lib/client.js
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/knex/lib/knex-builder/Knex.js:1:16)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/knex/lib/index.js:1:14)
|
||||
97.78 ms across 1 load(s) :: ./isMatch/index.js
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/date-fns/index.js:1797:40)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
97.67 ms across 1 load(s) :: node_modules/date-fns/isMatch/index.js
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/date-fns/index.js:1797:40)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
97.10 ms across 1 load(s) :: ../parse/index.js
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/date-fns/isMatch/index.js:8:37)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/date-fns/index.js:1797:40)
|
||||
96.91 ms across 1 load(s) :: node_modules/date-fns/parse/index.js
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/date-fns/isMatch/index.js:8:37)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/date-fns/index.js:1797:40)
|
||||
95.34 ms across 1 load(s) :: ./repository
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/unleash-client/src/unleash.ts:4:1)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/unleash-client/src/index.ts:2:1)
|
||||
95.11 ms across 1 load(s) :: node_modules/unleash-client/lib/repository/index.js
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/unleash-client/src/unleash.ts:4:1)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/unleash-client/src/index.ts:2:1)
|
||||
93.45 ms across 1 load(s) :: ../request
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/unleash-client/src/repository/index.ts:9:1)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/unleash-client/src/unleash.ts:4:1)
|
||||
93.21 ms across 1 load(s) :: node_modules/unleash-client/lib/request.js
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/unleash-client/src/repository/index.ts:9:1)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/unleash-client/src/unleash.ts:4:1)
|
||||
89.85 ms across 1 load(s) :: make-fetch-happen
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/unleash-client/src/request.ts:1:1)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/unleash-client/src/repository/index.ts:9:1)
|
||||
89.48 ms across 1 load(s) :: node_modules/make-fetch-happen/lib/index.js
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/unleash-client/src/request.ts:1:1)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/unleash-client/src/repository/index.ts:9:1)
|
||||
85.40 ms across 1 load(s) :: ./_lib/parsers/index.js
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/date-fns/parse/index.js:20:16)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/date-fns/isMatch/index.js:8:37)
|
||||
85.08 ms across 1 load(s) :: node_modules/date-fns/parse/_lib/parsers/index.js
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/date-fns/parse/index.js:20:16)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/date-fns/isMatch/index.js:8:37)
|
||||
79.73 ms across 1 load(s) :: swagger-parser
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/@wesleytodd/openapi/index.js:4:23)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
79.59 ms across 1 load(s) :: node_modules/swagger-parser/index.js
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/@wesleytodd/openapi/index.js:4:23)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
79.55 ms across 1 load(s) :: @apidevtools/swagger-parser
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/swagger-parser/index.js:2:18)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/@wesleytodd/openapi/index.js:4:23)
|
||||
79.35 ms across 1 load(s) :: node_modules/swagger-parser/node_modules/@apidevtools/swagger-parser/lib/index.js
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/swagger-parser/index.js:2:18)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/@wesleytodd/openapi/index.js:4:23)
|
||||
79.16 ms across 1 load(s) :: ./fetch.js
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/make-fetch-happen/lib/index.js:4:15)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/unleash-client/src/request.ts:1:1)
|
||||
78.91 ms across 1 load(s) :: node_modules/make-fetch-happen/lib/fetch.js
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/make-fetch-happen/lib/index.js:4:15)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/unleash-client/src/request.ts:1:1)
|
||||
73.35 ms across 1 load(s) :: ./cache/index.js
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/make-fetch-happen/lib/fetch.js:7:15)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/make-fetch-happen/lib/index.js:4:15)
|
||||
73.08 ms across 1 load(s) :: node_modules/make-fetch-happen/lib/cache/index.js
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/make-fetch-happen/lib/fetch.js:7:15)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/make-fetch-happen/lib/index.js:4:15)
|
||||
72.33 ms across 1 load(s) :: ./entry.js
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/make-fetch-happen/lib/cache/index.js:2:20)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/make-fetch-happen/lib/fetch.js:7:15)
|
||||
72.06 ms across 1 load(s) :: node_modules/make-fetch-happen/lib/cache/entry.js
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/make-fetch-happen/lib/cache/index.js:2:20)
|
||||
at at TracingChannel.traceSync (node:diagnostics_channel:322:14)
|
||||
at at Object.<anonymous> (node_modules/make-fetch-happen/lib/fetch.js:7:15)
|
||||
|
||||
Tips: move DB connect/migrations after listen(); lazy-load heavy routes; avoid sync FS; defer remote config/secret fetches; inspect "Slow module loads" and "Top PROMISE stacks" (tune with STARTUP_* env vars).
|
||||
1331334
startup-trace.json
Normal file
1331334
startup-trace.json
Normal file
File diff suppressed because it is too large
Load Diff
Loading…
Reference in New Issue
Block a user