In a Laravel food-ordering app, how would you write a middleware that times each request, adds the duration to the response, and logs slow ones?

## The goal A food-ordering app has a checkout that sometimes feels slow. The team wants every response to carry its server-side duration, and any request slower than 500 ms to be logged with enough context to find it later. A middleware is the natural place: it sees every request it wraps, before and after the controller. ## Where each line goes A Laravel middleware's `handle(Request $request, Closure $next): Response` runs in two halves around the call to `$next`: 1. **Before `$next`**: the controller has not run yet. This is where the start time is captured. 2. **The call itself**: `$response = $next($request);` runs every inner middleware and the route action, and returns their response. 3. **After `$next`**: the response exists. This is where the duration is computed, the header set and the log written. 4. **Return**: the (possibly modified) response goes back out to the middleware that wrapped this one. ```php public function handle(Request $request, Closure $next): Response { $start = hrtime(true); $response = $next($request); $ms = round((hrtime(true) - $start) / 1e6, 1); $response->headers->set('Server-Timing', "app;dur={$ms}"); if ($ms > $this->thresholdMs) { Log::warning('Slow request', [ 'method' => $request->method(), 'path' => $request->path(), 'ms' => $ms, ]); } return $response; } ``` ## Choices worth defending in an interview - **`hrtime(true)`** returns nanoseconds from a monotonic clock, so it is unaffected by system clock adjustments. `microtime(true)` works but can jump if the clock is corrected. - **Modifying the response** uses Symfony's `$response->headers->set()`, which exists on every response type because they all extend `Symfony\Component\HttpFoundation\Response`. - **Structured context** in the log call (`['path' => ..., 'ms' => ...]`) keeps the log searchable; never log request bodies from a checkout, which may contain card or address data. - **The threshold** belongs in config, injected through the constructor, not hard-coded in `handle()`. ## What the number actually measures The measurement starts when this middleware runs and stops when `$next` returns. That has consequences: | Where the middleware is registered | What the duration includes | |---|---| | Prepended to the global stack | Almost all framework work plus the controller | | Appended to the `web` group | Session start, CSRF and binding are outside; controller and route middleware inside | | On one route | Only that route's inner middleware and controller | It never includes the time PHP and the framework spent **before** the pipeline started (autoloading, bootstrapping providers), nor the time spent **sending** the response. For a `StreamedResponse`, the callback that produces the body runs when the response is sent, after `handle()` has returned, so a slow stream looks fast here. ## Failed requests are timed too If the controller throws, for example a payment exception during checkout, Laravel's routing pipeline catches it inside the inner layer, lets the exception handler render an error response, and returns that response to the layers outside it. `$next($request)` in the timing middleware therefore still returns normally, with a 500 or 422 response, so the header is set and slow failures are logged like any other request. Only an exception thrown by the timing middleware's own code skips its header and log lines; the pipeline then renders that exception at the timing middleware's layer instead. Redirects behave the same way: a `RedirectResponse` is still a response, so a slow `POST /checkout` that ends in a redirect to the confirmation page is timed and logged. ## When the after-phase is the wrong place Two pieces of work fit better after the response is delivered: - Writing to a slow log destination, which delays the user's response by the time the write takes. - Anything that must see the **full** request duration, including sending. Laravel offers a `terminate(Request $request, Response $response)` method on middleware for exactly that: it runs after the response has been sent under PHP-FPM. Moving the `Log::warning` call there keeps the header in `handle()` and the log write out of the user's wait. ## Testing it An HTTP test can hit an ordering route and assert the header exists: - `$this->get('/menu')->assertHeader('Server-Timing')` checks the after-phase ran. - Keep the threshold configurable so a test can set it to zero and exercise the slow-request path without sleeping.