Eclipse microprofile metrics @Timed does measure time, always 0

Question

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

Setup is with Payara 5 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:

@ApplicationScoped
public class Coffees {


    @Counted(name = "total_coffees_retrieved", absolute = true, monotonic = true)
    @Timed   
    public String retrieveCoffee() {
        try {
            Thread.sleep((int) (1000 * Math.random()));
        } catch (InterruptedException ex) {
            Logger.getLogger(Coffees.class.getName()).log(Level.SEVERE, null, ex);
        }

        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>

Any ideas how to solve this?

EDIT: does not occur when requesting metrics with application/json

curl -H "Accept: application/json" http://localhost:8080/metrics/application

Issue is already solved for one of the next payara releases: https://github.com/payara/Payara/issues/2970

Answer 1

If you want to see something other than 0 you will need to have a method that takes some more time to execute! Simply incrementing a counter and returning a string like that will take hardly any time at all, definitely far less than 0.1 seconds, so you'll never see any value in your metrics.

Try adding Thread.sleep(1500) to the method to see if the timer logs 1.5 seconds.

Since @Timed gives you lots of statistics, you could also try Thread.sleep(Math.random() * 1000) to give you some variation in the amount of time it takes to execute and give you more interesting metrics to examine.

Edit: As mentioned in the comments below, there appears to be a bug in Payara Micro 5.182 which results in the timer not working.