Merge pull request #12 from thelastbackspace/feat/real-app-fixes

Fixes from running traceperf on a real app (Prisma's REST example)

Author: thelastbackspace

CHANGELOG.md

@@ -8,8 +8,19 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 ## [Unreleased]
 
 ### Added
-- **Prisma without code changes:** `traceperf/auto` and `traceperf run` track every Prisma Client call (`prisma.User.findMany`, raw queries as `prisma.raw.$queryRaw SELECT users`), including clients made with `$extends`. `instrumentPrisma(tp, require('@prisma/client'))` does it by hand. `prismaExtension` steps aside when this is active, so calls are not counted twice.
+- **Prisma without code changes (5, 6 and 7):** `traceperf/auto` and `traceperf run` track every Prisma Client call (`prisma.User.findMany`, raw queries as `prisma.raw.queryRaw`) through Prisma's own tracing hook, so it works with clients generated anywhere (Prisma 7's `prisma-client`), `$extends` and driver adapters, and keeps `@prisma/instrumentation` (OpenTelemetry) working. `instrumentPrisma(tp)` does it by hand; `prismaExtension` steps aside when it is active.
 - **better-sqlite3, and so Drizzle on SQLite:** `instrumentBetterSqlite3`; auto-detected. Drizzle on pg or mysql2 was already covered through those drivers.
+### Changed (from running it on Prisma's REST example, not just the planted apps)
+- **Grouped findings show the typical case**, not the worst: one cold start no longer makes every request look slow. The worst is mentioned (`typical shown; worst 191 ms`), and a finding seen in under 5% of 20+ requests is dropped as noise; otherwise its share is given (`in 1 of 172 GET /feed`).
+- "X took 97% of the request" is no longer said of a request that makes a single call, unless that call takes 100 ms or more.
+- Sequential or repeated calls made *inside* a driver or ORM call (Prisma's `include` runs two queries) are not reported: the app can't reorder them.
+- Blocking inside a dependency or Node.js internals gets "the time is inside pg (library code)…" instead of "move it to a worker thread".
+- `traceperf run`: queueing with nothing blocking is described as the app's throughput limit, with what to do about it.
+- SQL labels read quoted names: `"public"."Post"` → `SELECT public.Post` (was `SELECT public`).
+
+### Fixed
+- `traceperf run -- npx tsx app.ts` hung after the load and left the app running: only `npx` was stopped. The app now runs in its own process group, which is stopped as a whole (also on Ctrl-C and when `run` itself is terminated).
+
 - N+1 fixes name the Prisma (`include`, `where: { id: { in } }`) and Drizzle (`inArray`) way.
 
 ## [1.4.0] - 2026-11-06

src/__tests__/drivers.test.ts

@@ -42,6 +42,8 @@ describe('sqlLabel', () => {
     ['/* hint */ select 1', 'SELECT'],
     [{ text: 'DELETE FROM t' }, 'DELETE t'],
     [{ sql: 'select a from b join c' }, 'SELECT b'],
+    ['SELECT "public"."Post"."id" FROM "public"."Post" WHERE 1', 'SELECT public.Post'],
+    ['select * from `shop`.`orders`', 'SELECT shop.orders'],
     ['BEGIN', 'BEGIN'],
     [undefined, 'QUERY'],
   ])('%p -> %p', (sql, label) => {
@@ -252,56 +254,66 @@ describe('instrumentAwsClient (real AWS SDK v3 client, local endpoint)', () => {
   });
 });
 
-describe('instrumentPrisma (client shaped like Prisma 6: every call goes through _request)', () => {
-  // Checked by hand against @prisma/client 6.19 (model calls, $extends clients, raw queries)
-  class FakePrisma {
-    _originalClient = this;
-    _request(params: any): Promise<unknown> {
-      return new Promise((resolve, reject) => setTimeout(() => (params.args?.fail ? reject(new Error('P2002')) : resolve([])), 2));
-    }
-    get user() { return { findMany: (args?: any) => this._request({ model: 'User', action: 'findMany', clientMethod: 'user.findMany', args }) }; }
-    $queryRawUnsafe(sql: string) { return this._request({ action: 'queryRaw', clientMethod: '$queryRawUnsafe', args: [sql] }); }
-    $extends() { return Object.create(this._originalClient, { _appliedParent: { value: this } }); }
-  }
+describe('instrumentPrisma (client that uses the tracing hook the way Prisma 5-7 does)', () => {
+  // Checked by hand against @prisma/client 6.19 and 7.0 (generated client, pg adapter)
+  const g = globalThis as any;
+  const helper = () => g.V7_PRISMA_INSTRUMENTATION?.helper ?? g.PRISMA_INSTRUMENTATION?.helper ??
+    { runInChildSpan: (_o: unknown, fn: () => unknown) => fn() };
+  const fakePrisma = {
+    _op(model: string | undefined, method: string, fail = false) {
+      return helper().runInChildSpan({ name: 'operation', attributes: { method, model } }, () =>
+        helper().runInChildSpan({ name: 'serialize' }, () =>
+          new Promise((resolve, reject) => setTimeout(() => (fail ? reject(new Error('P2002')) : resolve([])), 2))));
+    },
+    user: { findMany: (fail?: boolean) => fakePrisma._op('User', 'findMany', fail) },
+    $queryRaw: () => fakePrisma._op(undefined, 'queryRaw'),
+  };
 
-  test('model calls, raw queries, extended clients and failures', async () => {
+  test('model calls, raw queries and failures; uninstall restores the hook', async () => {
     const { tp, roots } = setup();
-    const uninstall = instrumentPrisma(tp, { PrismaClient: FakePrisma });
-    expect(instrumentPrisma(tp, FakePrisma)).toBeInstanceOf(Function); // idempotent
-    const prisma = new FakePrisma().$extends();
+    const uninstall = instrumentPrisma(tp);
+    expect(instrumentPrisma(tp)).toBeInstanceOf(Function); // idempotent
     await tp.track(async () => {
-      await prisma.user.findMany();
-      await prisma.$queryRawUnsafe('SELECT * FROM "User" WHERE id = 1');
-      await prisma.user.findMany({ fail: true }).catch(() => undefined);
+      await fakePrisma.user.findMany();
+      await fakePrisma.$queryRaw();
+      await fakePrisma.user.findMany(true).catch(() => undefined);
     }, { label: 'GET /users' });
-    expect(labels(roots[0])).toEqual(['prisma.User.findMany', 'prisma.raw.$queryRawUnsafe SELECT User', 'prisma.User.findMany']);
+    expect(labels(roots[0])).toEqual(['prisma.User.findMany', 'prisma.raw.queryRaw', 'prisma.User.findMany']);
     expect(roots[0].children[2].error).toBeInstanceOf(Error);
     uninstall();
+    expect('PRISMA_INSTRUMENTATION' in g).toBe(false);
     roots.length = 0;
-    await tp.track(() => prisma.user.findMany(), { label: 'after' });
+    await tp.track(() => fakePrisma.user.findMany(), { label: 'after' });
     expect(labels(roots[0])).toEqual([]);
   });
 
-  test('prismaExtension stands aside while the client is patched (no double counting)', async () => {
+  test('OpenTelemetry instrumentation that is already there keeps getting its spans', async () => {
+    const seen: string[] = [];
+    const otel = { helper: {
+      isEnabled: () => true, getTraceParent: () => 'tp', dispatchEngineSpans: () => undefined, getActiveContext: () => undefined,
+      runInChildSpan: (o: any, fn: () => unknown) => { seen.push(o.name); return fn(); },
+    } };
+    g.V7_PRISMA_INSTRUMENTATION = otel;
     const { tp, roots } = setup();
-    const ext = prismaExtension(tp).query.$allModels.$allOperations;
-    const call = () => ext({ model: 'User', operation: 'findMany', args: {}, query: async () => [] });
-    const uninstall = instrumentPrisma(tp, FakePrisma);
-    await tp.track(() => call(), { label: 'patched' });
+    const uninstall = instrumentPrisma(tp);
+    expect(helper().isEnabled()).toBe(true);
+    await tp.track(() => fakePrisma.user.findMany(), { label: 'r' });
+    expect(labels(roots[0])).toEqual(['prisma.User.findMany']);
+    expect(seen).toEqual(['operation', 'serialize']);
     uninstall();
-    await tp.track(() => call(), { label: 'extension only' });
-    expect(roots.map(r => [r.label, labels(r)])).toEqual([['patched', []], ['extension only', ['prisma.User.findMany']]]);
+    expect(g.V7_PRISMA_INSTRUMENTATION).toBe(otel);
+    delete g.V7_PRISMA_INSTRUMENTATION;
   });
 
-  test('a client instance works too; unknown objects are ignored', async () => {
+  test('prismaExtension stands aside while the hook is installed (no double counting)', async () => {
     const { tp, roots } = setup();
-    const client = new FakePrisma();
-    const uninstall = instrumentPrisma(tp, client);
-    await tp.track(() => client.user.findMany(), { label: 'r' });
-    expect(labels(roots[0])).toEqual(['prisma.User.findMany']);
+    const ext = prismaExtension(tp).query.$allModels.$allOperations;
+    const call = () => ext({ model: 'User', operation: 'findMany', args: {}, query: async () => [] });
+    const uninstall = instrumentPrisma(tp);
+    await tp.track(() => call(), { label: 'hooked' });
     uninstall();
-    expect(() => instrumentPrisma(tp, {})()).not.toThrow();
-    expect(() => instrumentPrisma(tp, undefined)()).not.toThrow();
+    await tp.track(() => call(), { label: 'extension only' });
+    expect(roots.map(r => [r.label, labels(r)])).toEqual([['hooked', []], ['extension only', ['prisma.User.findMany']]]);
   });
 });
 

src/__tests__/explain-auto-profile.test.ts

@@ -72,6 +72,15 @@ describe('explain()', () => {
     expect(formatFindings([blocking])).toMatch(/\n {3}fix: hashPassword/);
     expect(explain([hash]).find(f => f.kind === 'blocking')!.fix).toMatch(/worker_threads/);
     expect(explain([node('boom', 0, 10, { error: new Error('x') })])[0].fix).toBeUndefined();
+    const lib = { login: [{ functionName: 'submit → Writable.uncork', location: 'node_modules/pg/lib/query.js:177', ms: 16 }] };
+    expect(explain([hash], { hotspots: lib }).find(f => f.kind === 'blocking')!.fix).toMatch(/^the time is inside pg \(library code\)/);
+  });
+
+  test("a library's own sequential or repeated calls are not reported", () => {
+    const include = node('GET /feed', 0, 40, { children: [
+      node('prisma.Post.findMany', 0, 40, { children: [node('pg SELECT public.Post', 0, 20), node('pg SELECT public.User', 20, 20)] }),
+    ] });
+    expect(explain([include]).filter(f => f.kind === 'sequential' || f.kind === 'repeated')).toEqual([]);
   });
 
   test('blocking is attributed to the deepest call that did it', () => {
@@ -88,7 +97,7 @@ describe('explain()', () => {
     const page = node('page', 0, 60, { children: seq, selfDuration: 0 });
     const queries = Array.from({ length: 6 }, (_, i) => node('pg SELECT items', i * 2, 2));
     const list = node('list', 0, 20, { children: queries, selfDuration: 8 });
-    const slow = node('report', 0, 100, { children: [node('render', 0, 90)], selfDuration: 10 });
+    const slow = node('report', 0, 100, { children: [node('render', 0, 90), node('cache.get', 90, 5)], selfDuration: 5 });
     const failed = node('save', 0, 3, { children: [node('pg INSERT', 0, 2, { error: new Error('duplicate key') })], error: new Error('duplicate key') });
     const findings = explain([page, list, slow, failed]);
     const by = (kind: string) => findings.filter(f => f.kind === kind);
@@ -110,7 +119,24 @@ describe('explain()', () => {
     }));
     const seq = explain(roots).filter(f => f.kind === 'sequential');
     expect(seq).toHaveLength(1);
-    expect(seq[0].message).toMatch(/seen 5 times, worst shown/);
+    expect(seq[0].message).toMatch(/seen 5 times, typical shown\)$/);
+  });
+
+  test('grouped findings show the typical case: one cold start does not make every request look slow', () => {
+    // A request that makes one call is always mostly that call: not worth saying unless it is slow
+    expect(explain([node('GET /a', 0, 21, { selfDuration: 1, children: [node('db', 0, 20)] })])).toEqual([]);
+    expect(explain([node('GET /a', 0, 151, { selfDuration: 1, children: [node('db', 0, 150)] })])[0].kind).toBe('dominant');
+    // 9 requests where the query is 4 ms of 5 ms, one where the first connection made it 110 ms
+    const roots = [110, ...Array(9).fill(4)].map(ms => node('GET /users', 0, ms + 1, { selfDuration: 0.5, children: [node('db', 0, ms), node('auth', ms, 0.5)] }));
+    const [once] = explain(roots).filter(f => f.kind === 'dominant');
+    expect(once.message).toMatch(/\(in 1 of 10 GET \/users\)$/);
+    // ... and once in 40 requests is noise
+    const many = [110, ...Array(39).fill(4)].map(ms => node('GET /users', 0, ms + 1, { selfDuration: 0.5, children: [node('db', 0, ms), node('auth', ms, 0.5)] }));
+    expect(explain(many).filter(f => f.kind === 'dominant')).toEqual([]);
+    const slowRoots = [110, 40, 42, 41, 39].map(ms => node('GET /users', 0, ms + 1, { selfDuration: 0.5, children: [node('db', 0, ms), node('auth', ms, 0.5)] }));
+    const [f] = explain(slowRoots).filter(x => x.kind === 'dominant');
+    expect(f.ms).toBe(41);
+    expect(f.message).toMatch(/\(41 ms of 42 ms\) \(seen 5 times, typical shown; worst 110 ms\)$/);
   });
 
   test('nothing to say', () => {

src/__tests__/run.test.ts

@@ -250,6 +250,11 @@ describe('queueFindings', () => {
     ];
     const findings = queueFindings(load, trees, 'GET');
     expect(findings).toHaveLength(1);
-    expect(findings[0].message).toContain('GET /ping took 0.2 ms in the app (median) but clients waited 190 ms');
+    expect(findings[0].message).toContain('GET /ping took 0.2 ms in the app (median) but clients waited 190 ms');    expect(findings[0].message).toMatch(/see blocking code above/);
+    expect(findings[0].fix).toBeUndefined();
+    // Nothing blocked: the app is simply at its throughput limit
+    const [busy] = queueFindings({ ...load, requests: 800, durationMs: 1000 }, trees, 'GET', false);
+    expect(busy.message).toMatch(/waited their turn .* \(800 requests\/s here\)$/);
+    expect(busy.fix).toMatch(/throughput limit/);
   });
 });

src/auto.ts

@@ -95,7 +95,7 @@ export function autoInstrument(tp: OptimizedPerformanceMonitor, options: AutoIns
     if (deps.names.has('pg')) add('pg', () => instrumentPg(tp, load('pg')));
     if (deps.names.has('mysql2')) add('mysql2', () => instrumentMysql2(tp, load('mysql2')));
     if (deps.names.has('better-sqlite3')) add('better-sqlite3', () => instrumentBetterSqlite3(tp, load('better-sqlite3')));
-    if (deps.names.has('@prisma/client')) add('prisma', () => instrumentPrisma(tp, load('@prisma/client')));
+    if (deps.names.has('@prisma/client')) add('prisma', () => instrumentPrisma(tp));
     if (deps.names.has('ioredis')) add('ioredis', () => instrumentRedis(tp, load('ioredis')));
     if (deps.names.has('mongodb')) add('mongodb', () => instrumentMongo(tp, load('mongodb')));
     else if (deps.names.has('mongoose')) {