Ability to measure request time. Logging middleware

[maxtotheguenther]

Describe the feature you'd like to request

Hey guys,

Currently im trying to measure the time nextjs needs for serving the response.
For this use case I tried to implement this logic inside a "global" /pages/_middleware.ts.

export function middleware(req: NextRequest, event: NextFetchEvent) {
  const start = performance.now();
  const response = NextResponse.next();

  // Something like
  response.on("finish", () => {
    const duration = performance.now() - start;
    // log it baby
  });
}

Unfortunately NextResponse does not provide any possibility to do so.
So I cannot add an event listener. Is there a way to implement such logic?
The logging example provided in the Middleware documentation is missing!

Describe the solution you'd like

I want a possibility to measure the actual response time of a request.

Describe alternatives you've considered

The Express Request Interface inherits a class called Writable where you have the possibility to register event listeners.

class Writable extends Stream implements NodeJS.WritableStream {
  ...
  on(event: "close", listener: () => void): this;
  on(event: "drain", listener: () => void): this;
  on(event: "error", listener: (err: Error) => void): this;
  on(event: "finish", listener: () => void): this;
  on(event: "pipe", listener: (src: Readable) => void): this;
  on(event: "unpipe", listener: (src: Readable) => void): this;
  on(event: string | symbol, listener: (...args: any[]) => void): this;
  ...
}

It would be great if the interface NextResponse also had such methods.

[weyert]

Yeah, the whole telemetry story is a bit disappointing. I think the only approach is to go the custom server route and then write a custom Express middleware. Only then you have the problem again that you can't resolve the API route name from the url's path name causing a high cardinality for your metrics. You could then mess around with trying to detect your route variables with some regex and then replace then with some token e.g. {id} or something but hat ain't great either.

I do think you might be able to do it via waitUntil?

[weyert]

@timneutkens Did say during the Next 12 announcement that they are working on a tracing and metrics concept for Next.js but I haven't heard much about it since then.

[maxtotheguenther]

@weyert The suggestion with waitUnitl could possibly work. I'll give it a try!
Thank you!

[maxtotheguenther]

@weyert
Correct me if I'm wrong, but NextReponse is just an initial response object not the actual response. I never get to the actual response that is sent to the client. Consequently I don't have the possibility to wait for the actual response.

See: #34436

import { NextResponse } from 'next/server';

async function middleware(req, event) {
  const response = NextResponse.next();
  const waited = (res, ev) => new Promise(async (resolve, reject) => {
    res.text()
      .then((text) => {
        /* do something here with text */
        resolve();
      });
  });

  event.waitUntil(waited(response, event));
  return response;
}

export default middleware;

[arturenault]

+1 on this, also trying to figure it out. Would love some help here.

It's frustrating because the docs mention that this should be possible using waitUntil, but there's no explanation of how: https://nextjs.org/docs/api-reference/next/server#nextfetchevent

[nibtime]

+1. I recently got a warning from Vercel about CPU utilization but the averages in Vercel Dashboard don't show any problems.

I can't use performance.now() and process.hrtime() to measure execution time and also not process.cpuUsage() to measure CPU utilization, they are not defined in middleware.

The Vercel Support replied to me that I should measure and log middleware execution in my latest production build, but I have really no clue how to do that.

Some guidance on that in docs would be great. All I can do atm to test this is guess and hammer preview builds with requests to observe averages. Not ideal.

console.time and console.timeEnd work for measuring execution time. However with console.timeEnd() you can just write to stdout instantly and not capture the execution time value for structured logging.

[weyert]

Yes, I am still waiting for @timneutkens update regarding support for tracing and metrics in Next.js.

I had hoped that by now we would have automatic instrumentation using Opentelemetry :(

[nibtime]

Having integrated perf telemetry built into Next.js would be the most ideal solution of course.

As a start, I would be satisfied with a guide on how to measure basic performance metrics with the edge runtime.

[nibtime]

I added a very basic guide for middleware tracing to the docs of a lib of mine that uses middleware: https://next-safe-middleware.vercel.app/guides/trace-middleware

It's not much. For the moment I log to console and connected Logtail as a logging sink to Vercel. Better than nothing, but real tracing from Next.js would be much better,

Middleware execution time logs in Logtail

[marcinlesek]

Hey! Thanks for raising this.

Do you know any updates on this? Unfortunately, I'm looking for a similar solution, and I can't find anything (neither in official docs nor googling).

Thanks for any tips on how you solved that!

[weyert]

Only by patching Next.js itself. I am doing that via some Opentelemetry instrumentation. I hope Vercel will add support for this

[tabuchid]

@weyert Could you provide a example of how you are patching with Opentelemetry instrumentation?
I'd like to do this with our FE and have been struggling to understand how it would work.

[cplaetzinger]

+1 on this. The current implementation of middleware does not allow such a feature.

[faisalsayed10]

Are there any updates on this?

[adam187]

I had same issue, what I ended it for now it to patch next start-server
https://github.com/vercel/next.js/blob/canary/packages/next/src/server/lib/start-server.ts#L172
using https://www.npmjs.com/package/patch-package and putting my logger there

server.on('request', (request, response) => {
    // put logging here
})

[ORESoftware]

wonder how that works with edge/lambdas?

[ORESoftware]

it needs to be a middleware feature, there's no way to put this on all api and server actions etc, it's not a good idea

I thought about using some sort of Proxy magic

import { NextResponse } from 'next/server';

export function middleware(req) {
  const response = NextResponse.next();

  // Create a Proxy to trap reads
  const p = new Proxy({}, {
    get(target, prop) {
      if (prop === 'toString') {
        console.log('Header value was read!');
        return () => 'triggered-value'; // Provide a default string value
      }
      return Reflect.get(target, prop);
    }
  });

  response.headers.set('X-Trigger-On-Read', p);

  return response;
}

but the above won't work and is dumb