http.client.requests and http.server.requests do not work as expected

[mateusz-nalepa]

Hey!

I'm making one issue due to fact, that I was using exactly the same test scenario, but with different configuration. I believe, that this will make it easier to understand what is going on.

I've already spoken about this with @marcingrzejszczak as a part of his free consultations, thank you once again @marcingrzejszczak for this opportunity!

Bug in visual form

Configuration

• http.client.requests:
  • web app
  • server with virtual threads
  • RestClient with ReactorClientHttpRequestFactory
• http.server.requests:
  • WebFlux app
  • Undertow server
  • WebClient with ReactorClientHttpConnector

Version:

• Spring Boot 3.5.4

How to reproduce

Everything is here, please check readme file
https://github.com/mateusz-nalepa/spring-http-client-server-seconds-bug-MCVE

Potential places how to fix it

• http.client.requests
  • DefaultWebClient.DefaultRequestBodyUriSpec#exchange
    • do not start observation for http.client here, instead start http.client.pending
    • make sure http.client.pending metric/observation starts on server thread
  • ExchangeFunctions.DefaultExchangeFunction#exchange
    • end observation for http.client.pending
    • start observation for http.client
    • make sure, both of this happens on client thread
• http.server.requests
  • TomcatVirtualThreadsWebServerFactoryCustomizer
  • instead of new VirtualThreadExecutor("tomcat-handler-")
  • do something like

    new MonitoredExecutor(
                    new VirtualThreadExecutor("tomcat-handler-")
                )


    class MonitoredExecutor internal constructor(private val delegate: Executor) : Executor {
        override fun execute(runnable: Runnable) {
            delegate.execute(MonitoredRunnable(runnable))
        }
    }

    class MonitoredRunnable internal constructor(private val delegate: Runnable) : Runnable {
        private val startTime = System.nanoTime()

        override fun run() {
            val duration = Duration.ofNanos(System.nanoTime() - startTime)
            VirtualLogger.log(this, "Http server pending request took: $duration")

            delegate.run()
        }
    }

Very important note

I've provided only two configurations of server + client. But probably the same applies for other servers/clients.

Why is this important?

In classical old approach test scenario takes 19s as expected.
In webflux/virtual in takes 27s and we are blind.

[bclozel]

Thanks very much for the detailed report.

If I understand correctly, the main problem here is that the observability instrumentation in Spring Framework:

• for "http.server.requests", only the request/response processing time is measured, and the time this exchange spent waiting to be processed is not taken into account
• for "http.client.requests" this is the opposite, we are not only measuring the time it took for the request/response to happen, but also the time waiting for resources to be available

In some way, both expectations have opposite goals. On the server side you would like to measure as much as possible, as soon as the connection is established with the client. On the client side, you would like to measure as little as possible and only start the clock when the connection is established.

I think that there is no strong definition for those conventions (including in the OTel space I believe), mostly because of the wide variety of implementations out there. I think that the most sensible approach is to measure things at the level of the instrumentation. Here, in Spring Framework, we can really only measure things consistently from a web framework perspective.

I think that applications should consider disabling Framework instrumentations and use server-specific instrumentations (like the Tomcat code snippet you provided) instead if they're a better fit for their observation model. I think a Micrometer Tomcat Valve is still being considered. We could in theory change the client instrumentation as you suggested, but I think that other developers might argue that they want to know about this wait time.

Overall, I don't think we want to introduce a new observation for http.*.pending as we're gearing towards adopting OTel semantics in the portfolio and we should not deviate from the standard.