Fix APM trace start time

In #96205 we started recording the start time of the authn phase of REST
request processing, because this happens too early to even start a span
for the request. However we capture the threadpool's cached time which
can be 200ms slow, yielding spans that appear much longer than they
should. This commit moves to capturing the time using
`System.currentTimeMillis` to avoid this problem.

Backport of #98113 to 8.9

Author: DaveCTurner

docs/changelog/98113.yaml

@@ -0,0 +1,5 @@
+pr: 98113
+summary: Fix APM trace start time
+area: Infra/Core
+type: bug
+issues: []

server/src/main/java/org/elasticsearch/action/ActionModule.java

@@ -581,7 +581,7 @@ public ActionModule(
     public void copyRequestHeadersToThreadContext(HttpPreRequest request, ThreadContext threadContext) {
         // the request's thread-context must always be populated (by calling this method) before undergoing any request related processing
         // we use this opportunity to first record the request processing start time
-        threadContext.putTransient(Task.TRACE_START_TIME, Instant.ofEpochMilli(threadPool.absoluteTimeInMillis()));
+        threadContext.putTransient(Task.TRACE_START_TIME, Instant.ofEpochMilli(System.currentTimeMillis()));
         for (final RestHeaderDefinition restHeader : headersToCopy) {
             final String name = restHeader.getName();
             final List<String> headerValues = request.getHeaders().get(name);

server/src/test/java/org/elasticsearch/http/AbstractHttpServerTransportTests.java

@@ -56,6 +56,7 @@
 
 import java.net.InetSocketAddress;
 import java.net.UnknownHostException;
+import java.time.Instant;
 import java.util.ArrayList;
 import java.util.Arrays;
 import java.util.Collection;
@@ -68,6 +69,7 @@
 import java.util.Set;
 import java.util.concurrent.CountDownLatch;
 import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicReference;
 
 import static java.net.InetAddress.getByName;
 import static java.util.Arrays.asList;
@@ -82,9 +84,11 @@
 import static org.hamcrest.Matchers.containsInAnyOrder;
 import static org.hamcrest.Matchers.containsString;
 import static org.hamcrest.Matchers.equalTo;
+import static org.hamcrest.Matchers.greaterThanOrEqualTo;
 import static org.hamcrest.Matchers.hasSize;
 import static org.hamcrest.Matchers.instanceOf;
 import static org.hamcrest.Matchers.is;
+import static org.hamcrest.Matchers.lessThanOrEqualTo;
 import static org.hamcrest.Matchers.notNullValue;
 import static org.hamcrest.Matchers.nullValue;
 import static org.mockito.Mockito.mock;
@@ -324,6 +328,7 @@ protected void populatePerRequestThreadContext(RestRequest restRequest, ThreadCo
      */
     public void testTraceParentAndTraceId() {
         final String traceParentValue = "00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01";
+        final AtomicReference<Instant> traceStartTimeRef = new AtomicReference<>();
         final HttpServerTransport.Dispatcher dispatcher = new HttpServerTransport.Dispatcher() {
 
             @Override
@@ -332,7 +337,8 @@ public void dispatchRequest(final RestRequest request, final RestChannel channel
                 assertThat(threadContext.getHeader(Task.TRACE_PARENT_HTTP_HEADER), nullValue());
                 assertThat(threadContext.getTransient("parent_" + Task.TRACE_PARENT_HTTP_HEADER), equalTo(traceParentValue));
                 // request trace start time is also set
-                assertThat(threadContext.getTransient(Task.TRACE_START_TIME), notNullValue());
+                assertTrue(traceStartTimeRef.compareAndSet(null, threadContext.getTransient(Task.TRACE_START_TIME)));
+                assertNotNull(traceStartTimeRef.get());
             }
 
             @Override
@@ -371,14 +377,10 @@ protected HttpServerChannel bind(InetSocketAddress hostAddress) {
                 }
 
                 @Override
-                protected void doStart() {
-
-                }
+                protected void doStart() {}
 
                 @Override
-                protected void stopInternal() {
-
-                }
+                protected void stopInternal() {}
 
                 @Override
                 public HttpStats stats() {
@@ -391,11 +393,20 @@ protected void populatePerRequestThreadContext(RestRequest restRequest, ThreadCo
                 }
             }
         ) {
+            final var systemTimeBeforeRequest = System.currentTimeMillis();
             transport.dispatchRequest(fakeRequest, channel, null);
+            final var systemTimeAfterRequest = System.currentTimeMillis();
             // headers are "null" here, aka not present, because the thread context changes containing them is to be confined to the request
             assertThat(threadPool.getThreadContext().getHeader(Task.TRACE_ID), nullValue());
             assertThat(threadPool.getThreadContext().getHeader(Task.TRACE_PARENT_HTTP_HEADER), nullValue());
             assertThat(threadPool.getThreadContext().getTransient("parent_" + Task.TRACE_PARENT_HTTP_HEADER), nullValue());
+
+            // system clock is not _technically_ monotonic but in practice it's very unlikely to see a discontinuity here
+            assertThat(
+                traceStartTimeRef.get().toEpochMilli(),
+                allOf(greaterThanOrEqualTo(systemTimeBeforeRequest), lessThanOrEqualTo(systemTimeAfterRequest))
+            );
+
             transport.dispatchRequest(null, null, new Exception());
             // headers are "null" here, aka not present, because the thread context changes containing them is to be confined to the request
             assertThat(threadPool.getThreadContext().getHeader(Task.TRACE_ID), nullValue());