Unaccounted time loss / "gaps" before and after a request hits a mapped queries @Component

[roookeee]

We have recently switched to ExpediaGroups GraphQL after migrating a Kotlin REST based service to GraphQL.

Since switching our Jaeger Traces show gaps before and after the last database query / span is created:

There is no computation heavy work done before or after performing the aforementinoned database queries besides trivial entity -> DTO mapping. An initial investigation via VisualVM has shown no obvious hotspots but we are losing an overall of 3-6ms in a local environment (dev, prod suffer even more) which increases the overall response time by 100%.

We are at a loss where to go from here: Is it a WebFlux issue? Is it a issue in regards to this library? We are executing all of our logic in a separate ThreadPool which is not saturated (these results are present for one client non-concurrently calling our GraphQL endpoint) so we shouldn't block the event loop of Netty (even if we did: it shouldn't create those "gaps" if my understanding of Webflux is correct).

I am looking for a way to further investigate this issue or any configuration knobs.

The "gaps" in between the database calls have been identified to be framework related and can be circumvented by restructuring our code, the head and tail "gaps" cannot be accounted for in profilers / worked around. Furthermore we are not losing any tracing related information across thread boundaries, that has been accounted for.

Additional information:

• Our response size on average is below 1 kb
• There is no reverse proxy in front of this service in a local environment which also exhibits this issue
• All traffic is HTTP, not HTTPS
• We are making extensive use of suspend fun

[tapaderster]

is there an example app to recreate this?

[roookeee]

Here you go, the contained README.md contains all the necessary information. Check multiple reported spans, we are "losing" 1-4ms in front and 1-2ms in the "back" - the example sleeps for 12ms and should in theory respond close to said 12 ms. The Thread.sleep is wrapped by a new span to differentiate the gap before and after a successful request. The issue is more pronounced in a real world scenario - our endpoints could (in theory) respond in 6-10ms but actually take 18-25ms.
expediagroup-perf-demo.zip

[roookeee]

We did some digging (see stackoverflow answer) - the main TL;DR I would offer is that PreparsedDocumentProvider should have a more prominent mention in the documentation, the other stuff is just JVM warmup related.