Implement Server Timing performance metrics

I love this!

We could add more detail, which is what #2851733: Expose collected metrics via Server-Timing response header suggested. But … that also means much more bikeshedding. This is simple. We can have follow-ups to add more detail. But that detail could potentially be used in an adversarial way (e.g. exposing DB query time would enable malicious users to figure out the most expensive route, and then hit that route in a DDoS attack).

That risk doesn't exist in this patch.

I know you're only adding it to development.services.yml so the aforementioned risks don't really apply, but wouldn't it be great to expose at least the "total" timing always, also on production sites? That's a key goal of the Server Timing spec: https://www.w3.org/TR/server-timing/#server-timing-for-automated-analytics

1. +++ b/core/lib/Drupal/Core/StackMiddleware/ServerTiming.php
   @@ -0,0 +1,44 @@
   +   * The kernel.
   

   Übernit: The decorated kernel.

2. +++ b/core/lib/Drupal/Core/StackMiddleware/ServerTiming.php
   @@ -0,0 +1,44 @@
   +    $response->headers->set('Server-Timing', 'total;desc="Total";dur=' . $duration);
   

   Nit: this is not setting the $replace parameter. Which means its default is used: $replace = TRUE. That means this call is overwriting any pre-existing Server-Timing response header. We should instead be merging these.

   (And ideally we'd have test coverage proving that this appends to any existing Server-Timing response header, instead of overwriting it.)

   P.S.: I touched on something similar last week: https://git.drupalcode.org/project/http2_server_push/commit/fc0cc00.

Exciting progress, @Chi!

1. +++ b/core/tests/Drupal/Tests/Core/StackMiddleware/ServerTimingTest.php
   @@ -0,0 +1,37 @@
   +    ClockMock::register(__CLASS__);
   +    ClockMock::withClockMock($_SERVER['REQUEST_TIME_FLOAT'] + 0.123123);
   

   FANCY!

2. +++ b/core/tests/Drupal/Tests/Core/StackMiddleware/ServerTimingTest.php
   @@ -0,0 +1,37 @@
   +    $http_kernel = $this->createMock('Symfony\Component\HttpKernel\HttpKernelInterface');
   

   $this→prophesize(HttpKernelInterface::class)→reveal() is nowadays the preferred way of doing this.

3. +++ b/core/tests/Drupal/Tests/Core/StackMiddleware/ServerTimingTest.php
   @@ -0,0 +1,37 @@
   +    self::assertEquals('total;desc="Page execution time";dur=123.12', $response->headers->get('Server-Timing'));
   

   $this→assertSame() is nowadays preferred.

Yes, I think this should have a change record, to make as many people aware as possible :)

I think it'd be great to add test coverage for the edge case I described in #7.2 — now that there is a unit test, it's easy to test that 🥳

1. 👍 Change record looks great!

2. +++ b/core/tests/Drupal/Tests/Core/StackMiddleware/ServerTimingTest.php
   @@ -0,0 +1,49 @@
   +   * Tests Server-Timing header.
   

   🤔 Nit: Can change to just @covers ::handle I think?

3. +++ b/core/tests/Drupal/Tests/Core/StackMiddleware/ServerTimingTest.php
   @@ -0,0 +1,49 @@
   +  public function testServerTiming() {
   +
   +    ClockMock::register(__CLASS__);
   

   🤓 Nit: extraneous empty line.

Those are übertrivial nits though, and not worth holding this patch up for.

I understand not making this development only since it's viable to want it enabled on production, but do we really want to enable it on production for every site? It's a syscall to get the microtime for the request, and even if you want this on production, you'd have to make a conscious effort to use it I think? Wondering if we want a tiny module to do this instead.

you'd have to make a conscious effort to use it I think

I'm not sure what you mean by "conscious effort" here. It's available to any end user (which includes developers of the site) as well as analytics (Google Analytics or otherwise).

It does bloat every single response with an extra header, which some sites might not want? There is also perhaps a better chance of something like a crypto-related timing attack if you can more accurately measure how long a request took?

I think a small module makes sense, or if not, perhaps the behavior could be toggled on and off in a similar manner to the way cache tag headers ( X-Drupal-Cache-Tags)?

@WimLeers you have to make a conscious effort to use analytics no?

+++ b/core/lib/Drupal/Core/StackMiddleware/ServerTiming.php
@@ -0,0 +1,44 @@
+  public function handle(Request $request, $type = self::MASTER_REQUEST, $catch = TRUE) {
+    $response = $this->httpKernel->handle($request, $type, $catch);

+++ b/core/tests/Drupal/Tests/Core/StackMiddleware/ServerTimingTest.php
@@ -0,0 +1,48 @@
+    $http_kernel->handle(Argument::type(Request::class), HttpKernelInterface::MASTER_REQUEST, TRUE)
+      ->willReturn($response);

It should not fire on subrequests and that needs test coverage

#26:
RE: extra header: it compresses to nearly nothing and we've got far worse bloat in our responses, such as X-Generator which has definitely no value at all. You're right in absolute terms of course! :) But in relative terms, I don't see significant cost here.
RE: crypto-related timing attacks relate to response size and very precise differences in timing. Drupal response times do not depend on crypto logic, but on data retrieval and assembling a response. If Drupal were extremely tightly optimized and had extremely low-latency I/O for its data retrieval, then I would share this concern. Right now, this is a concern I would love to have 🤓😄

#30: Good point. But if analytics have already been set up, then this enables them to provide richer insights without any additional conscious effort.

+1 for me.

#28: I agree, it doesn't seem needed to add a new module for this. I also don't think we need to add a configuration option for this in the UI. That could alway be added later.

#31: That does seem like something we can add, I'm not sure if we need to add this in this patch, I think we can add this in the future as a followup to this?

I reviewed the patch and it looks great, I'm sitting next to @Wim Leers at the global sprint weekend and he explained why we should implement this. +1.

btw Probably it needs review from project manager pov

+++ b/core/lib/Drupal/Core/StackMiddleware/ServerTiming.php
@@ -0,0 +1,44 @@
+    // The request stack is already empty at this point so that
+    // \Drupal::time()->getRequestMicroTime() cannot be used here.
+    $duration = round(1000 * (microtime(TRUE) - $_SERVER['REQUEST_TIME_FLOAT']), 2);

The request stack is empty but we have the request - so we can do $request->server->get('REQUEST_TIME_FLOAT') instead of $_SERVER['REQUEST_TIME_FLOAT']

It'd be great to get a +1 from @catch

FWIW I think this patch and approach is okay. If you don't want this information exposed you can remove the service but it seems helpful to expose by default and it is not exposing anything that represents a security risk.

@Chi maybe this middleware should check that only for master request?

Added https://github.com/symfony/symfony/pull/27985/files to summary - SF adopted this header too

+++ b/core/lib/Drupal/Core/StackMiddleware/ServerTiming.php
@@ -0,0 +1,42 @@
+    $response->headers->set('Server-Timing', 'total;desc="Page execution time";dur=' . $duration, FALSE);

I suggest to use kinda "Request execution time" because not all requests produce a Page

Code looks good, and this is nice.

To address the concerns from previous comments, perhaps we could add a link to the change record on how to remove this.

Test Failed to #41, Moving to Needs Work

I bet it proper branch

I think we should only be adding this in 9.1.x now as both 8.9.x and 9.0.x are in beta.
#46 is failing because \Symfony\Component\HttpFoundation\HeaderBag::get() with 3 arguments is deprecated in Symfony 4.

So that means

+++ b/core/tests/Drupal/Tests/Core/StackMiddleware/ServerTimingTest.php
@@ -0,0 +1,51 @@
+    self::assertSame($expected_headers, $response->headers->get('Server-Timing', NULL, FALSE));

Should be:
self::assertSame($expected_headers, $response->headers->all('Server-Timing'));

+++ b/core/lib/Drupal/Core/StackMiddleware/ServerTiming.php
@@ -0,0 +1,44 @@
+    $response = $this->httpKernel->handle($request, $type, $catch);
+    if ($type == self::MASTER_REQUEST) {
+      $duration = round(1000 * (microtime(TRUE) - $request->server->get('REQUEST_TIME_FLOAT')), 2);
+      $response->headers->set('Server-Timing', 'total;desc="Request execution time";dur=' . $duration, FALSE);
+    }
+    return $response;

There's no test coverage of the condition if ($type == self::MASTER_REQUEST) { as far as I can see.

Great tests! Back to rtbc

Nice work on this; it's an interesting proposal.

I think we need an explicit signoff from the framework managers here: @alexpott indicated he was OK with it, but @catch had some questions and I think we still need some final consensus/signoff.

If we're going to add this without an additional module, I think we need profiling to see if the call to microtime() makes a measurable difference with the internal page cache (this is also a reason not to use the config system since that'd need to be checked in the internal page cache too, unless we introduce a dependency between the configuration value and the container).

microtime() results in a syscall that we otherwise usually avoid via the various request time superglobals.

Rerolled the last patch (3104566-52.patch) as per the issue tag. Please review it.

I think this is a worthwhile change, even considering the new microtime() call on page cached pages. If thats going to be a blocker, could we remove this feature when page cache is successful for a given page or even when its enabled on the site? Just looking for a compromise.

other side of "disabled by default" is that just few people will use it as new setting for sure will be skipped

Proposal 3, making a separate module for it, allows it to be discovered easily while solving the other problems?

@longwave do you mean experimental telemetry module and initiative?

Why not just a small core module? page_cache is one service and a cache bin, automated_cron is one service and some config. server_timing module could just add this one service?

I think the compromise could be reversion to the original approach. which is having server timing only in development environment.

That sounds good to me.

For development time there's better tools now like https://github.com/brettmc/opentelemetry-php-contrib/blob/main/src/Instr...