DEV Community

Cover image for Your ORM is hiding the line that caused the slow query
Juan Versolato Lopes
Juan Versolato Lopes

Posted on

Your ORM is hiding the line that caused the slow query

I was building a runtime N+1 query detector for Node. The detection part worked on the first afternoon. Getting it to tell you which line of your code caused the problem took considerably longer, and taught me something about how ORMs execute queries that I had not thought about before.

This is that story, and the fix.

The symptom

The detector instruments your database driver. When the same query shape runs many times inside one request, it reports it — along with the file and line that issued it, which is the part that actually saves you time:

nplusone 1 finding in GET /orders — 51 queries, 840ms

  N+1 query  50× SELECT * FROM items WHERE order_id = ?
     at src/routes/orders.ts:47:38  (loadOrdersPage)
     612ms spent here
Enter fullscreen mode Exit fullscreen mode

That worked. Then I pointed it at an app using Drizzle and got this instead:

  N+1 query  12× select "id", "order_id" from "items" where "items"."order_id" = $1
     <unknown call site>
Enter fullscreen mode Exit fullscreen mode

Detected, counted, and attributed to nothing.

Do not theorise. Dump the stack

My first instinct was that my frame filter was too aggressive — it skips node_modules, node:internal, and the library's own frames, so maybe it was eating something it should not have.

Rather than guess, I printed the whole stack at the exact moment the driver was called:

const originalQuery = pg.Client.prototype.query;

pg.Client.prototype.query = function (...args) {
  const previous = Error.stackTraceLimit;
  Error.stackTraceLimit = 100;
  const stack = new Error().stack.split("\n").slice(1);
  Error.stackTraceLimit = previous;

  console.log("FRAMES:", stack.length);
  stack.forEach((line, i) => {
    const mine = !/node_modules|node:internal/.test(line);
    console.log(`${String(i).padStart(3)} ${mine ? ">>>" : "   "} ${line.trim()}`);
  });

  return originalQuery.apply(this, args);
};
Enter fullscreen mode Exit fullscreen mode

Here is what came back for a single await db.select().from(items).where(...):

FRAMES: 12
  0     at Proxy.<anonymous> (.../nplusone/dist/adapters/postgresjs.js)
  1     at .../drizzle-orm/postgres-js/session.js
  2     at PostgresJsPreparedQuery.queryWithCache (.../drizzle-orm/...)
  3     at .../drizzle-orm/...
  4     at Object.startActiveSpan (.../drizzle-orm/...)
  5     at .../drizzle-orm/...
  6     at Object.startActiveSpan (.../drizzle-orm/...)
  7     at PostgresJsPreparedQuery.execute (.../drizzle-orm/...)
  8     at .../drizzle-orm/...
  9     at Object.startActiveSpan (.../drizzle-orm/...)
 10     at PgSelectBase.execute (.../drizzle-orm/...)
 11     at PgSelectBase.then (.../drizzle-orm/...)
Enter fullscreen mode Exit fullscreen mode

Twelve frames. Not one of them belongs to the application. My filter was innocent — there was nothing to find.

Why the frames are gone

Look at frame 11: PgSelectBase.then.

A Drizzle query is a lazy thenable. db.select().from(items).where(...) does not run anything — it builds an object. The query executes when something calls .then() on it, and when you write await, the thing calling .then() is the JavaScript runtime, not your code.

By that point your function has already returned. Its frame is gone from the stack. The runtime picks the thenable up from the microtask queue and calls into Drizzle, and the whole call chain from there down belongs to the ORM.

So the information is not being filtered out. It no longer exists.

TypeORM does not have this problem

This is where it gets interesting, because I assumed every ORM would behave the same way. I measured instead of assuming, and TypeORM came out fine:

repo.find()                  6x  patterns.js:31 (loadItemsForOrder)
repo.findOne()               6x  patterns.js:36
createQueryBuilder()         6x  patterns.js:42
ds.query() raw               6x  patterns.js:47
Enter fullscreen mode Exit fullscreen mode

Line numbers, function names, everything.

The difference is who triggers execution. repo.find() is an async function that you call. Node keeps async stack traces across await boundaries inside that chain, so your frame survives all the way down to the driver.

Drizzle's await is on a thenable you built but did not call. That is the distinction — not "Drizzle is worse", but "lazy execution moves the call out of your stack".

Worth remembering next time you look at a stack trace and it seems too short.

Getting the line back

The stack is useless at execution time. But there is a moment when the caller is on the stack: while the query is being built. db.select().from(items).where(...) is a plain synchronous chain of method calls.

So: capture the call site during construction, carry it to execution, and let the driver-level instrumentation use it instead of walking the stack.

Carrying it is the interesting half, because construction and execution are separated by an await. That is exactly what AsyncLocalStorage is for:

import { AsyncLocalStorage } from "node:async_hooks";

const storage = new AsyncLocalStorage<CallSite>();

/** Runs `fn` with `callsite` visible to anything underneath it. */
export function runWithCallSite<T>(callsite: CallSite | undefined, fn: () => T): T {
  if (callsite === undefined) return fn();
  return storage.run(callsite, fn);
}

/** The call site published by an ORM adapter, if any. */
export function ambientCallSite(): CallSite | undefined {
  return storage.getStore();
}
Enter fullscreen mode Exit fullscreen mode

The driver adapter then prefers the ambient value over its own stack walk:

export function captureNow(): CallSite | undefined {
  const ambient = ambientCallSite();
  if (ambient !== undefined) return ambient;

  return captureCallSite();  // the stack walk, for drivers called directly
}
Enter fullscreen mode Exit fullscreen mode

And the ORM side wraps the builder so that chaining preserves the call site, and executing publishes it:

function wrapChain<T>(value: T, callsite: CallSite | undefined): T {
  return new Proxy(value as object, {
    get(target, property, receiver) {
      const inner = Reflect.get(target, property, receiver);
      if (typeof inner !== "function") return inner;

      // `.then()` / `.execute()` — the query is running now.
      if (EXECUTION_METHODS.has(property as string)) {
        return (...args: unknown[]) =>
          runWithCallSite(callsite, () => inner.apply(target, args));
      }

      // `.from()`, `.where()`, `.limit()` — still building.
      return (...args: unknown[]) => {
        const result = inner.apply(target, args);
        if (result === target) return receiver;   // chained `this`
        return wrapChain(result, callsite);
      };
    },
  }) as T;
}
Enter fullscreen mode Exit fullscreen mode

The call site is captured once, when you call db.select(), and travels with the builder through every chained method until something executes it.

Net result: the SQL comes from the driver, the line number comes from the ORM.

The result

Same query, same app, before and after:

- N+1 query  12× select "id", "order_id", "name" from "items" where "items"."order_id" = $1
-    <unknown call site>

+ N+1 query  12× select "id", "order_id", "name" from "items" where "items"."order_id" = $1
+    at drizzle-test.mjs:35
Enter fullscreen mode Exit fullscreen mode

That is the actual before and after from the same script, against PostgreSQL 16,
Drizzle 0.45.2 and postgres.js 3.4.9 — real database, not fixtures. Line 35 is
where db.select() is called inside the loop.

One trap worth knowing

The first version of this had a bug that took a while to see: I treated .values() as an execution method.

In postgres.js, .values() executes a query. In Drizzle, db.insert(t).values({...}) builds an insert. Treating it as execution broke the chain, so every insert silently lost its attribution — while selects kept working perfectly.

If you write something like this, be precise about which methods in your target library actually execute, and test inserts separately from selects. A bug that only affects half your cases is worse than one that breaks everything, because you will not notice it.

Two things I would tell past me

Measure before theorising. I was ready to rewrite my frame filter. The filter was fine. Ten minutes printing the actual stack saved an afternoon of fixing the wrong thing.

"It works" and "it works with real inputs" are different claims. Every unit test passed while this bug existed, because fixtures call the driver directly and the caller's frame is right there. Only running against a real ORM exposed it.


The detector is nplusone — MIT, zero runtime dependencies, and it turns off when NODE_ENV=production. If you want to see the output without wiring anything up:

import { configure, record } from "nplusone";

configure({ autoScope: true });
for (const id of [1, 2, 3, 4, 5]) {
  record({ sql: "SELECT * FROM items WHERE order_id = $1", params: [id] });
}
Enter fullscreen mode Exit fullscreen mode

But honestly, the stack trace thing is the part I found interesting, and it applies to anything you instrument — tracing, logging, profiling. If your tool reports "unknown" where a line number should be, dump the stack. The answer is usually right there.

Top comments (2)

Collapse
 
mads_hansen_27b33ebfee4c9 profile image
Mads Hansen

Capturing at construction time is a clever recovery of information that execution-time stacks have genuinely lost. The next edge case I’d test is attribution semantics when a builder is created in one place and executed somewhere else.

A repository helper may call db.select(), return the builder, and a route may add the predicate or execute it inside a loop. “First construction site” would then point to the generic helper rather than the line that created the N+1 behavior. Reused/prepared builders and concurrent Promise.all executions make that distinction even sharper.

It may be useful to retain two origins: builder-created-at and execution-context-at, with an explicit override/span for adapters that know the semantic call site. Then regression-test nested AsyncLocalStorage scopes, builder reuse across requests, transactions, inserts, and concurrent execution to prove attribution cannot bleed between requests. The post’s larger lesson is excellent: instrumentation needs real integration fixtures because the abstraction changes what evidence still exists.

Collapse
 
truta446 profile image
Juan Versolato Lopes

You're right, and I went and measured it rather than reasoning about it — which felt appropriate given the post.

Three shapes, against the adapter as it stands:

Shape Reported Where the N+1 actually is
Helper builds, route executes in a loop line 33, inside baseQuery the loop, line 38
Builder created once, reused in a loop line 43, outside the loop the loop, line 45
Promise.all, inline construction line 53 ✅ line 53

So the first two are exactly the failure you described. And it is worse than being unhelpful: it is confidently wrong. Reporting sends someone looking; reporting a generic repository helper sends them to the wrong file believing they have the answer.

Your two-origin suggestion is the right shape, and there is a detail that makes it more recoverable than I first thought. In the helper case, .where(i) is called from the loop, synchronously — the caller is on the stack at that exact moment. Capturing on the last chained call before execution, rather than only the first, would fix shapes 1 and 2.

It would not fix everything. If the whole chain lives inside the helper —

function q(id) { return db.select().from(items).where(eq(items.id, id)); }

— then the last construction call is still in the helper. Which is precisely why keeping both origins beats swapping one heuristic for another: you cannot pick a single capture point that is right in every shape, but you can report both and let the reader see the difference.

Opened it as github.com/Truta446/nplusone/issue... with the measurements and the test list you outlined — nested scopes, builder reuse, transactions, inserts, and concurrent execution proving attribution cannot bleed across requests. That last one especially; AsyncLocalStorage should isolate them, but "should" is not a test.

And your closing line is the one I'd underline: the abstraction changes what evidence still exists. Every unit test in this project passed while the Next.js bug I mentioned was live, because fixtures call the driver directly and the caller's frame is right there. The fixture removed the very thing that breaks in production.