Timed annotation not working properly for reactive methods / futures

[nachogiljaldo]

Describe the bug
If you use the Timed annotation on a reactive method, it measures literally the time spent on the method, not the actual execution of the reactive action returned. Same happens with futures.

Expected behavior
Either it works or it should be validated so people doesn't get confusing results.

Actual behavior
It calculates the time creating the Uni/Multi/Future, but not the actual execution of the task itself.

To Reproduce

Create a method returning a Uni and annotate it with Timed, when you check the metrics, it does not match the reality.

Configuration
N/A

Screenshots
N/A

Environment (please complete the following information):

• Output of uname -a or ver:
• Output of java -version:
• GraalVM version (if different from Java):
• Quarkus version or git rev: 1.10.x, 1.11.x, 1.12.x (probably all older ones)
• Build tool (ie. output of mvnw --version or gradlew --version): Apache Maven 3.6.3 (cecedd343002696d0abb50b32b541b8a6ba2883f)

Additional context
N/A

[ebullient]

Can you confirm which version of Quarkus you're using, and which extensions you have enabled?

[nachogiljaldo]

@ebullient I'm using 1.10.5.FINAL and I tried it in 1.11.2.FINAL if I remember correctly.

I was using fault-tolerance extension along with Kafka, postgres-reactive and flyway.

[ebullient]

And which metrics extension? A reproducer would also help a lot, if that isn't asking too much

[geoand]

Is this still an issue?

[ebullient]

Yes.

[nachogiljaldo]

I can confirm this is still an issue with 2.6, I have a reproducer if that helps, what's the best way to send it to you? Just zip and upload here?

[geoand]

Sure, that works.

[nachogiljaldo]

Here it goes:
kafka-quickstart-processor.zip

It is a reactive kafka consumer that forces a random timeout, however, the metrics look wrong to me:

# HELP com_gilsoft_consumer_KafkaConsumer_custom_kafka_consumer_seconds_max  
# TYPE com_gilsoft_consumer_KafkaConsumer_custom_kafka_consumer_seconds_max gauge
com_gilsoft_consumer_KafkaConsumer_custom_kafka_consumer_seconds_max{scope="application",} 0.001248305

Let me know if that helps or you need anything, I'll try to be faster this time 🤦

[geoand]

Thanks for this info.

[ebullient]

I'm not sure of the right answer here, @geoand .. this is pretty standard fare for reactive methods: a @timed annotation can't really work there (as it can't follow the reactive chain properly.. there are too many variants). The @timed annotation can hitch itself to a completable future, but the last time @cescoffier and I talked about this, the more it seemed like metrics would need to be added explicitly, e.g. using logging: https://smallrye.io/smallrye-mutiny/guides/logging or by observing events: https://smallrye.io/smallrye-mutiny/getting-started/observing-events

[nachogiljaldo]

Although I am the original issue opener, I admit one could argue that the Timed annotation behaves as intended with its current behavior (after all it is measuring what the method takes to execute). So, an option could be just closing this issue, or adding a note in the documentation indicating this behavior and an example, as it can come a bit surprising.

That being said, I had a look at the code and it seems the magic happens at io.quarkus.micrometer.runtime.binder.mpmetrics.TimedInterceptor which knows nothing about distinct return types (not only reactive code bug also futures). One option could be make it smart about it and use https://smallrye.io/smallrye-mutiny/getting-started/observing-events#the-invoke-method as suggested for reactive and equivalent code for futures, but that would require inspecting the class of the result, which is "clean" for futures but given quarkus' metrics module knows nothing about mutiny it would some ugly class existence checks or entangling dependencies.

So TL;DR, it might be enough with enhancing the docs and closing the issue.

[geoand]

So yeah, annotations like @Timed which work by intercepting the execution of the method, don't work out of the box with reactive pipelines.
This is generally understood and accepted behavior, but in some cases it does make sense for us to go the extra mile to make them work, just because the annotations are so prevalent and the alternative adds a lot of complexity in user code. We did something similar for @Cached for example, to make the @Cached actually work when the applied on a method that returns a Uni.

[ebullient]

right. doable with a uni perhaps...

[israelstmz]

Hay, last week we shifted one of our production services from spring webflux to quarkus and we encountered this exact issue which took us by surprise since the FaultTolerance annotations do handle reactive operations nicely. We assumed the Metrics annotation will behave the same.
Here is where the FaultTolerance interceptor identifies an "async" flow:
https://github.com/smallrye/smallrye-fault-tolerance/blob/9afda4de4360584abc04564a723d68660393ab30/implementation/fault-tolerance/src/main/java/io/smallrye/faulttolerance/FaultToleranceInterceptor.java#L151
I believe the solution should be the same here.

[geoand]

Yup, just like @Cached works as well.

If I have time, I'll check it out.

[geoand]

#22639 should take care of it

[quarkus-bot]

/cc @ebullient, @jmartisk

[nachogiljaldo]

Thanks a bunch!

[geoand]

You are very welcome!