I Was Measuring LLM Latency Wrong

For a long time, I recorded one latency number for every LLM request:

latency_ms = response_finished_at - request_started_at

It looked useful. I could calculate an average, add a p95 chart, and see whether a model was getting slower.

But whenever a user complained that an AI feature felt slow, that number rarely told me what to fix.

Sometimes the request waited in a queue before reaching the provider. Sometimes the first token was slow, even though the rest of the response streamed quickly. Sometimes the model finished in two seconds and a tool call took another eight.

All of those cases appeared in my dashboard as “LLM latency.”

That was the problem. I was measuring a request, while the user was waiting for a feature.

One latency number hides several different problems

An LLM-powered feature usually has more stages than the API request itself:

User action
  -> application queue
  -> LLM request
  -> first token
  -> complete generation
  -> tool execution
  -> validation and persistence
  -> visible result

If I only record the time between sending the request and receiving the final token, I miss everything before and after it.

I now separate latency into at least five measurements:

• queue_ms: time spent waiting before the request starts
• ttft_ms: time from request start to the first useful token
• generation_ms: time from the first token to the final token
• tool_ms: time spent running tools or external actions
• end_to_end_ms: time from the original user action to the completed feature

These numbers answer different questions.

A high queue_ms points toward application capacity or concurrency limits. A high ttft_ms affects how responsive streaming feels. A high generation_ms may be related to output length or model behavior. A high tool_ms has little to do with model speed.

The user only sees end_to_end_ms.

A small Node.js latency tracker

Here is a minimal example using the OpenAI Node.js SDK. It also works with OpenAI-compatible APIs by setting LLM_BASE_URL.

Install the dependency:

npm install openai

Save this as latency-tracker.mjs:

import OpenAI from "openai";
import { performance } from "node:perf_hooks";

const client = new OpenAI({
  apiKey: process.env.LLM_API_KEY,
  baseURL: process.env.LLM_BASE_URL || undefined,
});

const model = process.env.LLM_MODEL;

if (!process.env.LLM_API_KEY || !model) {
  throw new Error(
    "Set LLM_API_KEY and LLM_MODEL before running this script."
  );
}

const round = (value) =>
  value == null ? null : Math.round(value * 100) / 100;

async function runMeasuredFeature({
  feature,
  messages,
  enqueuedAt = performance.now(),
  toolStep,
}) {
  const dequeuedAt = performance.now();
  const requestStartedAt = performance.now();

  let streamReadyAt = null;
  let firstTokenAt = null;
  let generationFinishedAt = null;
  let toolStartedAt = null;
  let toolFinishedAt = null;
  let output = "";

  try {
    const stream = await client.chat.completions.create({
      model,
      messages,
      stream: true,
    });

    streamReadyAt = performance.now();

    for await (const chunk of stream) {
      const text = chunk.choices[0]?.delta?.content ?? "";

      if (text && firstTokenAt === null) {
        firstTokenAt = performance.now();
      }

      output += text;
    }

    generationFinishedAt = performance.now();

    if (toolStep) {
      toolStartedAt = performance.now();
      await toolStep(output);
      toolFinishedAt = performance.now();
    }

    const featureFinishedAt = performance.now();

    const metrics = {
      feature,
      status: "success",
      queue_ms: round(dequeuedAt - enqueuedAt),
      stream_setup_ms: round(streamReadyAt - requestStartedAt),
      ttft_ms: round(
        firstTokenAt === null
          ? null
          : firstTokenAt - requestStartedAt
      ),
      generation_ms: round(
        firstTokenAt === null
          ? null
          : generationFinishedAt - firstTokenAt
      ),
      model_total_ms: round(
        generationFinishedAt - requestStartedAt
      ),
      tool_ms: round(
        toolStartedAt === null
          ? 0
          : toolFinishedAt - toolStartedAt
      ),
      end_to_end_ms: round(featureFinishedAt - enqueuedAt),
      output_characters: output.length,
    };

    console.log(JSON.stringify(metrics));

    return { output, metrics };
  } catch (error) {
    const failedAt = performance.now();

    const metrics = {
      feature,
      status: "failed",
      queue_ms: round(dequeuedAt - enqueuedAt),
      ttft_ms: round(
        firstTokenAt === null
          ? null
          : firstTokenAt - requestStartedAt
      ),
      elapsed_before_failure_ms: round(
        failedAt - requestStartedAt
      ),
      end_to_end_ms: round(failedAt - enqueuedAt),
      error_name: error.name,
      error_message: error.message,
    };

    console.error(JSON.stringify(metrics));
    throw error;
  }
}

const enqueuedAt = performance.now();

// In a real application, other queued work may happen here.

const result = await runMeasuredFeature({
  feature: "support_reply",
  enqueuedAt,
  messages: [
    {
      role: "user",
      content:
        "Explain why measuring only average LLM latency can be misleading.",
    },
  ],
});

console.log(result.output);

Run it with:

LLM_API_KEY="your-api-key" \
LLM_MODEL="your-model-name" \
node latency-tracker.mjs

A log entry will look like this:

{
  "feature": "support_reply",
  "status": "success",
  "queue_ms": 0.14,
  "stream_setup_ms": 482.31,
  "ttft_ms": 615.27,
  "generation_ms": 1388.42,
  "model_total_ms": 2003.69,
  "tool_ms": 0,
  "end_to_end_ms": 2004.18,
  "output_characters": 721
}

The values above are only an example of the log format. Actual results depend on the model, provider, prompt, output length, network, and application workload.

Time to first token is not total latency

Streaming made me realize that “fast” can mean two different things.

Consider two hypothetical requests:

Request A
TTFT:          300 ms
Generation:  4700 ms
Total:       5000 ms

Request B
TTFT:         2200 ms
Generation:  2800 ms
Total:       5000 ms

Both have the same total model latency. They do not feel the same.

Request A gives the user visible feedback almost immediately. Request B leaves the interface looking stuck for more than two seconds.

If I only chart total latency, I cannot see that difference. For interactive applications, I want a separate TTFT percentile instead of treating streaming as an implementation detail.

I also record the time of the first useful token, not simply the first stream event. Some APIs send metadata or an empty delta before content begins.

Average latency was hiding the requests I cared about

Averages are convenient and often misleading.

A few very slow requests can be hidden inside a reasonable average. Different features can also have completely different latency profiles.

A short classification call and a long report-generation call should not share the same latency chart just because they use the same model.

I now group latency by fields such as:

feature
model
provider
streaming
tool_name
status
prompt_version
output_size_bucket

Then I look at percentiles:

• p50 shows the typical experience
• p95 shows the slow experience that occurs regularly
• p99 helps expose severe outliers

I avoid placing raw user prompts in latency logs. Operational metadata is usually enough to identify whether the delay belongs to queuing, model generation, tool execution, or another application stage.

Model latency and feature latency need separate dashboards

This distinction changed how I interpreted performance incidents.

Suppose the model finishes quickly, but the feature still feels slow because it calls a search service, updates a database, and waits for another workflow.

Calling this an “LLM latency problem” sends me toward the wrong fix. Switching models will not make a slow database write faster.

I keep two related views now.

The model view tracks:

• time to first token
• generation time
• request failures
• output size
• model and provider

The feature view tracks:

• queue time
• full model time
• tool execution time
• validation time
• persistence time
• end-to-end completion time

The first view helps diagnose the inference layer. The second represents what the user actually experiences.

Failed requests need timing data too

Initially, I only emitted latency metrics after a successful response. That meant the slowest failures were absent from the dashboard.

A timeout after 30 seconds did not increase the latency chart because it never reached the success logging code.

That made the system look faster when it was less reliable.

Now failure logs include:

• elapsed time before failure
• whether any content had arrived
• the stage where the failure occurred
• retry attempt
• error category
• feature name

Success and failure latency should be analyzed together, while still being distinguishable. Otherwise, a dashboard can report healthy performance by quietly excluding the worst user experiences.

The metric I care about most

Provider latency still matters. I need it when evaluating models, investigating regressions, or configuring timeouts.

But it is no longer the main number I use to describe an AI feature.

The metric I care about most is:

Time from user action to a valid, visible, completed result

That definition forces me to include queues, retries, tools, validation, and persistence. It also prevents a fast model response from hiding a slow or broken workflow.

The model can be fast while the product is slow.

Once I measured the full path, latency stopped being a vague provider complaint and became a set of specific engineering problems I could actually investigate.

I work on TokenBay, so I spend a lot of time thinking about model and provider behavior. But the most useful latency lesson for me was broader: measure the feature boundary first, then break it down until every slow stage has an owner.