Incorrect exec time for child spans when using completable future in spring controller

[VasaviMadhurima]

Hi,

When diagnosing some performance issues, I noticed that the execution times for child spans in traces are incorrect for APIs that are implemented using Spring Async controller feature with Completable futures.

Here is a sample trace:

Take S3.HeadBucket child span for example - the waterfall view clearly shows that the exec time is 223ms. However, in the span summary we see that exec time is reported as 111ms (exactly half).

Below is a sample code to show how we use the Completable futures:

@GetMapping("/my-service-path")
public CompletableFuture<ResponseEntity<MyResponseObject>> getSomeInfo() {
    return CompletableFuture.supplyAsync(
        TracedSupplier.from(() -> {
            //internalServicelogic
         }),
    executorService
  );
}

Annoyances:

We extensively use Completable futures in spring controller for all our java services. Given this issue, the time spent charts incorrectly represent the time spent in the service v/s the downstream components. This defeats the purpose of using APM tracing to a large extent for us.

[VasaviMadhurima]

I can confirm that if we remove the Completable future and make the API implementation synchronous, the exec times of child spans look alright.

[amarziali]

👋 @VasaviMadhurima thanks for having opened that issue and sorry for the long wait. It should be fixed on 1.48.0 out early next week

[github-actions]

🤖 This issue has been addressed in the latest release. Check full details in the Release Notes.