What really happens when two requests share one console.time() label

console.time('checkout'), do some work, console.timeEnd('checkout'). It prints how long the work took. It’s the first stopwatch most of us ever use, and in a browser tab or a little script it is exactly right.

Put it on a server that handles two requests at once and it starts lying. That part is well known. What is almost always explained wrong — including in the draft of this very post, which is why I sat down and measured it — is how it lies.

The usual explanation goes: “the second console.time overwrites the first one’s start time.” That sounds reasonable. It is also not what Node does. I checked.

The experiment

Two requests, same label, overlapping. Request A is the slow one: it starts at 0ms and finishes at 80ms. Request B is the fast one: it starts a bit later, at 10ms, and finishes early, at 30ms.

const sleep = ms => new Promise(r => setTimeout(r, ms))

// A: starts at 0ms, ends at 80ms  → really takes 80ms
async function A () {
  console.time('cart')
  await sleep(80)
  process.stdout.write('A end -> ')
  console.timeEnd('cart')
}

// B: starts at 10ms, ends at 30ms → really takes 20ms
async function B () {
  await sleep(10)
  console.time('cart')
  await sleep(20)
  process.stdout.write('B end -> ')
  console.timeEnd('cart')
}

Promise.all([A(), B()])

Two requests, two real durations: 80ms and 20ms. Here is what Node v22 actually printed:

Warning: Label 'cart' already exists for console.time()
B end -> cart: 31.806ms
A end -> Warning: No such label 'cart' for console.timeEnd()

Read that carefully, because both lines are surprising.

Request B, which really took 20ms, reported 31.8ms. Not 20. It reported the time since A’s start, because A started the timer first and A’s start time is the one that survived.

Request A, which really took 80ms, reported nothing at all. No duration. Just a warning on stderr saying the label doesn’t exist.

So the second call doesn’t overwrite. It gets dropped.

That is the part everyone gets backwards, and it flips the whole failure mode around.

console.time(label) refuses to start a timer for a label that is already running. It warns and walks away, leaving the original start time untouched. Then the first timeEnd to fire — whoever finishes first, not whoever started first — grabs that single start time, prints a duration, and deletes the entry. Everybody else arriving later finds an empty cupboard.

So under concurrency you don’t get “slightly wrong numbers everywhere.” You get something much more specific and much more misleading:

• Short requests get inflated. They report the time since some other, earlier request started. B’s real 20ms was reported as 31.8ms.
• Long requests disappear entirely. The slow ones — the exact ones you opened the dashboard to find — are the ones most likely to still be running when someone else finishes and eats their timer. They produce no measurement at all.

That second one is the genuinely nasty part. Your p99 doesn’t get worse. Your p99 gets deleted. The measurements that vanish are systematically the slow ones, so the numbers you’re left with look healthier than reality. If you’re hunting a latency regression with data like this, the data is actively hiding the thing you’re looking for.

It’s not just Node

I ran the identical script on all three runtimes:

Same broken shape everywhere. Bun doesn’t even warn — it just quietly hands you the wrong number and drops the other one.

And even where the warning exists, be honest about where it lands: it’s a process warning on stderr, in a production server that’s already writing a lot to stderr. It is not going to catch anybody’s eye.

The fix: stop using a shared name as the key

Once you see the real problem, the fix is obvious. The label is a shared global key. Two requests using the same key are reaching into the same drawer. The fix isn’t a better key — it’s not having a shared drawer at all.

Instead of a name you look up later, get back a handle that holds its own start time and shares nothing with anyone:

export function createTimerHandle(
  label: string,
  emit: (message: string, data: unknown, durationMs: number) => void,
): TimerHandle {
  const started = now()          // private to this call
  let ended = false

  return {
    elapsed: () => roundMs(now() - started),
    end (data?: unknown): number {
      const durationMs = roundMs(now() - started)
      if (!ended) {              // ending twice logs once
        ended = true
        emit(`${label}: ${durationMs}ms`, data, durationMs)
      }
      return durationMs
    },
  }
}

That’s the whole trick. started lives inside the closure. Call it twice and you get two handles with two separate started values that cannot possibly collide. label is now just text for the message — it isn’t used to find anything.

In use it’s barely different from what you were already writing:

const timer = log.timer('checkout')
// ... work for THIS request only ...
timer.end({ orderId })

I re-ran my exact A/B race against this version. Both requests reported their own correct duration. No warnings, nothing dropped. Which is the boring result you want.

Three things the tests taught me that the docs didn’t

I was writing this post from the source code, felt smug about it, then ran the code and got surprised three times. Worth passing on.

1. Your timer is probably printing nothing in production

log.timer(label) emits its result at the debug level. In production the default minimum level is info. Debug is below info, so it is filtered out.

Meaning: you add a timer, deploy it, and get absolutely zero output. Not a wrong number — no number. Here’s the actual run, straight from my terminal:

--- default (production-like) ---
returned: 9.5
                         ← nothing logged

--- log.timer('db.query', 'info') ---
{"level":"info","message":"db.query: 10.3ms","data":{"rows":3,"durationMs":10.3}}

Two ways out, and pick based on what you want:

// just this one timer, promoted
const t = log.timer('db.query', 'info')

// or turn debug on globally (noisy — this affects everything)
configureLogger({ minLevel: 'debug' })

Note the return value still comes back either way — t.end() handed me 9.5 even while logging nothing. So if you’re feeding the duration into a metric yourself, you were fine. It’s only the log line that vanished.

2. .end() twice logs once, but doesn’t return the same number twice

The if (!ended) guard stops the double log line. It does not freeze the number. Every call recomputes from started:

first end returns  5.2
second end returns 5.4

This bites in the common pattern of calling .end() on the happy path and again in a finally. You’ll get one log line, correctly — but if you’re reading the return value from the finally call, it’s a slightly later number than the one that got logged. Capture the duration from the first call if it needs to match.

3. The “I can see hangs” feature is off by default

The best reason to wrap a whole function is hang detection. A function that never returns can’t log a completion line — by definition. The only thing that proves it was ever called is a line logged at the start:

export const createOrder = withLogging(
  async (formData: FormData) => { /* ... */ },
  { name: 'createOrder' },
)

You’d expect:

→ createOrder
✓ createOrder { durationMs: 84 }

What actually prints at default production settings is just this:

{"level":"info","message":"✓ createOrder","data":{"durationMs":11.7}}

The → entry line defaults to debug, same trap as the timer. So the hang-detection feature — the whole reason the entry line exists — is silently disabled in exactly the environment where you need it. Turn it on explicitly:

withLogging(handler, { name: 'createOrder', entryLevel: 'info' })

With that set, I started a function that never resolves, and the entry line showed up alone with no ✓ after it. That lonely arrow is the hang, visible.

What the wrapper does and doesn’t touch

Since it wraps your real code, I checked it stays out of the way:

• Errors come back untouched. I threw an error with a custom code: 'E42' property; the caught error still had code === 'E42' and the same message. It gets logged, then re-thrown as-is.
• Sync functions stay sync. Wrapping a plain function returned 'plain', not a Promise. The wrapper only awaits the result when it’s actually thenable — otherwise wrapping a synchronous route handler would quietly turn it async and break every caller.
• Timers are capped. Labelled timers are bounded at 1000. I started 1005 and checked: the oldest was evicted, the newest was fine. A timer you start and forget to end is a leak, and a bounded leak beats an unbounded one.

Why performance.now() and not Date.now()

Small detail, real consequence:

export function now(): number {
  return typeof performance !== 'undefined' && typeof performance.now === 'function'
    ? performance.now()
    : Date.now()
}

Date.now() reads the wall clock — the one that tells you what time it is, and the one NTP nudges forward or backward when it syncs. If that nudge lands in the middle of your request, Date.now() - started can come out wrong, or even negative, for reasons that have nothing to do with your code. performance.now() reads a monotonic clock, which only ever moves forward. It’s built for measuring elapsed time; Date is built for telling you the date. The Date.now() fallback is only there for runtimes where performance genuinely isn’t defined.

The takeaway

The thing worth carrying out of this isn’t really about console.time. It’s about any API that keeps state in one shared place keyed by a name you didn’t design to be unique — a module-level variable, a static map, a singleton. In a browser tab there’s one of everything and the assumption holds. On a server there isn’t, and it doesn’t.

When those APIs break, they usually don’t crash. They hand you a number that looks completely normal while quietly deleting the measurements that mattered most. Measure it yourself before you trust it — I assumed I understood this one, and I had it backwards until I ran the code.