microprofile metrics @timed does not measure times, always 0

[Wurznsepp]

Description

---

When using microprofile metrics, @timed annotation, this does (as it should) count the number of calls, but the mean/max/percentiles of the measured times are always "0".
Tested with Payara 5.182 full and micro.
The same application runs well on other applications servers.

More details here:
we have a problem with eclipse microprofile metrics @timed annotation. It does not seem to measure times (only counts number of calls).

Tested with Payara 5.x full, micro and 4.x full.

Typical output via http://localhost:8080/metrics/application:

    # TYPE application:total_coffees_retrieved counter
application:total_coffees_retrieved 4
# TYPE application:total_coffees_consumed counter
application:total_coffees_consumed 4
# TYPE application:com_sebastian_daschner_hello_prometheus_coffees_retrieve_coffee_rate_per_second gauge
application:com_sebastian_daschner_hello_prometheus_coffees_retrieve_coffee_rate_per_second 1.4044150172871745
# TYPE application:com_sebastian_daschner_hello_prometheus_coffees_retrieve_coffee_one_min_rate_per_second gauge
application:com_sebastian_daschner_hello_prometheus_coffees_retrieve_coffee_one_min_rate_per_second 0.0
# TYPE application:com_sebastian_daschner_hello_prometheus_coffees_retrieve_coffee_five_min_rate_per_second gauge
application:com_sebastian_daschner_hello_prometheus_coffees_retrieve_coffee_five_min_rate_per_second 0.0
# TYPE application:com_sebastian_daschner_hello_prometheus_coffees_retrieve_coffee_fifteen_min_rate_per_second gauge
application:com_sebastian_daschner_hello_prometheus_coffees_retrieve_coffee_fifteen_min_rate_per_second 0.0
# TYPE application:com_sebastian_daschner_hello_prometheus_coffees_retrieve_coffee_mean_seconds gauge
application:com_sebastian_daschner_hello_prometheus_coffees_retrieve_coffee_mean_seconds 0.0
# TYPE application:com_sebastian_daschner_hello_prometheus_coffees_retrieve_coffee_max_seconds gauge
application:com_sebastian_daschner_hello_prometheus_coffees_retrieve_coffee_max_seconds 0.0
# TYPE application:com_sebastian_daschner_hello_prometheus_coffees_retrieve_coffee_min_seconds gauge
application:com_sebastian_daschner_hello_prometheus_coffees_retrieve_coffee_min_seconds 0.0
# TYPE application:com_sebastian_daschner_hello_prometheus_coffees_retrieve_coffee_stddev_seconds gauge
application:com_sebastian_daschner_hello_prometheus_coffees_retrieve_coffee_stddev_seconds 0.0
# TYPE application:com_sebastian_daschner_hello_prometheus_coffees_retrieve_coffee_seconds summary
application:com_sebastian_daschner_hello_prometheus_coffees_retrieve_coffee_seconds_count 4
application:com_sebastian_daschner_hello_prometheus_coffees_retrieve_coffee_seconds{quantile="0.5"} 0.0
application:com_sebastian_daschner_hello_prometheus_coffees_retrieve_coffee_seconds{quantile="0.75"} 0.0
application:com_sebastian_daschner_hello_prometheus_coffees_retrieve_coffee_seconds{quantile="0.95"} 0.0
application:com_sebastian_daschner_hello_prometheus_coffees_retrieve_coffee_seconds{quantile="0.98"} 0.0
application:com_sebastian_daschner_hello_prometheus_coffees_retrieve_coffee_seconds{quantile="0.99"} 0.0
application:com_sebastian_daschner_hello_prometheus_coffees_retrieve_coffee_seconds{quantile="0.999"} 0.0

mean, max, quantiles are all "0.0", while count works well (= 4).

We have tried multiple combinations of Payara/JEE/Microprofile versions, each with the same result.

Here are some code snippets (base is taken from https://github.com/sdaschner/hello-prometheus/tree/microprofile, only added @timed)

Coffee-Bean:

public class Coffees {

    @Inject
    @Metric(name = "total_coffees_consumed", absolute = true)
    Counter coffeesConsumed;

    @Counted(name = "total_coffees_retrieved", absolute = true, monotonic = true)
    @Timed   
    public String retrieveCoffee() {
        coffeesConsumed.inc();
        return "Coffee!";
    }

}

JAX-RS REST Resource:

import javax.inject.Inject;
import javax.ws.rs.GET;
import javax.ws.rs.Path;

@Path("coffee")
public class CoffeesResource {

    @Inject
    Coffees coffees;

    @GET
    public String getCoffee() {
        return coffees.retrieveCoffee();
    }

}

pom.xml

<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
    <modelVersion>4.0.0</modelVersion>
    <groupId>com.sebastian-daschner</groupId>
    <artifactId>hello-prometheus</artifactId>
    <version>1.0-SNAPSHOT</version>
    <packaging>war</packaging>

    <dependencies>
        <dependency>
            <groupId>javax</groupId>
            <artifactId>javaee-api</artifactId>
            <version>7.0</version>
            <scope>provided</scope>
        </dependency>
        <dependency>
            <groupId>org.eclipse.microprofile.metrics</groupId>
            <artifactId>microprofile-metrics-api</artifactId>
            <version>1.1.1</version> <!-- also tried 1.0 and 1.1 -->
            <scope>provided</scope>
        </dependency>
    </dependencies>

    <build>
        <finalName>hello-prometheus</finalName>
    </build>

    <properties>
        <maven.compiler.source>1.8</maven.compiler.source>
        <maven.compiler.target>1.8</maven.compiler.target>
        <failOnMissingWebXml>false</failOnMissingWebXml>
        <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
    </properties>
</project>

Expected Outcome

Execution times of the annotates classes/methods should be measured and should not be "0"

Current Outcome

Measured times, min,max, percentiles are always "0"

Steps to reproduce (Only for bug reports)

See above

Environment

• Payara Version: 4.x and 5.x
• Edition: Full and Micro
• JDK Version: Oracle JDK 8
• Operating System: Windows
• Database: none

[svendiedrichsen]

Looks like a bug already fixed #2838

[Wurznsepp]

Yes... seems to be the same bug. When requesting application/json, everything is fine.
Thanks for the quick reply!

[svendiedrichsen]

@Wurznsepp You are welcome. Might wanna close this?

[Wurznsepp]

Sure... closed.