Timed - difference between Prometheus and JSON format

[rsvoboda]

There are differences in reported results between Prometheus and JSON format.
When using the same deployment with OpenLiberty there are no differences in reported results between Prometheus and JSON format.

Code

    @Timed(name = "itemsProcessed",
            description = "Metrics to monitor the times of processItem method. - @Timed",
            unit = MetricUnits.MINUTES,
            absolute = true)
    @GET
    @Path("/process")
    public Response processItem() {
        return Response.ok().build();
    }

SmallRye Metrics via WF:

curl http://127.0.0.1:9990/metrics/application/itemsProcessed -H "Accept: application/json"
{  "itemsProcessed" : {
    "p50": 5.619833333333334E-7,
    "p75": 5.619833333333334E-7,
    "p95": 5.619833333333334E-7,
    "p98": 5.619833333333334E-7,
    "p99": 5.619833333333334E-7,
    "p999": 5.619833333333334E-7,
    "min": 5.619833333333334E-7,
    "mean": 5.619833333333334E-7,
    "max": 5.619833333333334E-7,
    "stddev": 0.0,
    "count": 1,
    "meanRate": 7.975289185818699E-4,
    "oneMinRate": 0.0,
    "fiveMinRate": 0.0,
    "fifteenMinRate": 0.0
  }}

curl http://127.0.0.1:9990/metrics/application/itemsProcessed 2>/dev/null | grep -v TYPE | grep -v HELP
application:items_processed_rate_per_second 0.04784228234858272
application:items_processed_one_min_rate_per_second 0.0
application:items_processed_five_min_rate_per_second 0.0
application:items_processed_fifteen_min_rate_per_second 0.0
application:items_processed_min_seconds 2023140.0
application:items_processed_max_seconds 2023140.0
application:items_processed_mean_seconds 2023140.0
application:items_processed_stddev_seconds 0.0
application:items_processed_seconds_count 1.0
application:items_processed_seconds{quantile="0.5"} 2023140.0
application:items_processed_seconds{quantile="0.75"} 2023140.0
application:items_processed_seconds{quantile="0.95"} 2023140.0
application:items_processed_seconds{quantile="0.98"} 2023140.0
application:items_processed_seconds{quantile="0.99"} 2023140.0
application:items_processed_seconds{quantile="0.999"} 2023140.0

OpenLiberty:

curl https://localhost:9443/metrics/application/itemsProcessed -H "Accept: application/json" --insecure -u theUser:thePassword 2>/dev/null | jq
{
  "itemsProcessed": {
    "fiveMinRate": 0,
    "max": 38369,
    "count": 1,
    "p50": 38369,
    "p95": 38369,
    "p98": 38369,
    "p75": 38369,
    "p99": 38369,
    "min": 38369,
    "fifteenMinRate": 0,
    "meanRate": 0.0007829386932720206,
    "mean": 38369,
    "p999": 38369,
    "oneMinRate": 0,
    "stddev": 0
  }
}

curl https://localhost:9443/metrics/application/itemsProcessed --insecure -u theUser:thePassword 2>/dev/null | grep -v TYPE | grep -v HELP
application:items_processed_rate_per_second 7.827878570352143E-4
application:items_processed_one_min_rate_per_second 0.0
application:items_processed_five_min_rate_per_second 0.0
application:items_processed_fifteen_min_rate_per_second 0.0
application:items_processed_mean_seconds 3.8369000000000005E-5
application:items_processed_max_seconds 3.8369000000000005E-5
application:items_processed_min_seconds 3.8369000000000005E-5
application:items_processed_stddev_seconds 0.0
application:items_processed_seconds_count 1
application:items_processed_seconds{quantile="0.5"} 3.8369000000000005E-5
application:items_processed_seconds{quantile="0.75"} 3.8369000000000005E-5
application:items_processed_seconds{quantile="0.95"} 3.8369000000000005E-5
application:items_processed_seconds{quantile="0.98"} 3.8369000000000005E-5
application:items_processed_seconds{quantile="0.99"} 3.8369000000000005E-5
application:items_processed_seconds{quantile="0.999"} 3.8369000000000005E-5

Code: https://github.com/rsvoboda/rsvoboda-playground/blob/master/microprofile-metrics-hello-prometheus/src/main/java/com/sebastian_daschner/hello_prometheus/CoffeesResource.java#L69

[jmartisk]

merged in master, so AFAIK (there are no separated 2.0.x/1.1.x branches yet) it should be fixed in 1.1.3 and 2.0.0 when released

[kenfinnigan]

There's already a 1.x branch, and master should be moved to 2.x

[jmartisk]

Ok I'll send PRs with backports of my stuff from master to 1.x

[kenfinnigan]

Not sure things need to be backported, is there expectation of another 1.x release?

[jmartisk]

Well, is 1.x branch aiming for 1.2, 1.3, etc or 1.1.3, 1.1.4,etc.? (in the latter case it would make more sense if it were named 1.1.x). Are 1.1.x releases required for WildFly/EAP updates? @rsvoboda

[kenfinnigan]

I believe 1.x branch is aimed at 1.1.3 right now, however there won't be any 1.2 releases so I'm fine with it being 1.x right now.

I don't know what their plans are for updates at present.

[jmartisk]

Ok, in that case the backports to 1.x branch are valid and aimed towards 1.1.3, I suppose WildFly will use it at some point.

[kenfinnigan]

Maybe, but from an upstream perspective we're not planning to do a 1.1.3 release at all, as 2.0 will supersede it

[Ladicek]

I don't know what's the plan around the 2.0 release, but I spotted this problem in current Thorntail 2.3.0.Final-SNAPSHOT, and I know the problem wasn't there before (as we have a test for it in the Thorntail standalone test suite). So this is actually a regression.

If I wanted to have this fixed in Thorntail 2.3.0, would 1.1.3 be doable?

[kenfinnigan]

Based on the decision the other day for Metrics 2.0 to not be part of MP 2.2 in Feb, it would be fine to do another Metrics 1.x release.

@jmartisk, are there any other items that should be done before a release?

[jmartisk]

Currently the 1.x branch, compared to 1.1.2, fixes #40, #32, #33, #34, #37 and I'm not aware of any serious issue that should be fixed for 1.1.3, unless @rsvoboda has got any tips :)

[rsvoboda]

Can we get #39 fixed for 1.1.3 ?

[jmartisk]

Oh, I missed that, but #39 should be fixed along with #40 by Pull request #48

[rsvoboda]

I think we are good to go.

#42 and #43 have workarounds.
#11 and #36 could get some attention, but I don't think it's necessary for 1.1.3 release

[marekkopecky]

@jmartisk Looking to WF + SmallRye Matrics from 1.x branch, 2.8836E-5 / 60 = 4.806E-7

application:items_processed_seconds{quantile="0.5"} 2.8836E-5
"p50": 4.806E-7,
"unit": "minutes",

And to OpenLiberty:

application:items_processed_seconds{quantile="0.5"} 4.3196000000000005E-5
"p50":43196.0,
"unit":"minutes",

So the WF (with SmallRye Metrics 1.1.3-SNAPSHOT) has still different behaviour than OpenLiberty. Can you confirm that WF (with SmallRye Metrics 1.1.3-SNAPSHOT) doesn't violate the spec?

[jmartisk]

@marekkopecky I think SR is now correct on this. The difference is because JSON format uses the unit that you specify for your metric (https://github.com/eclipse/microprofile-metrics/blob/1.1/spec/src/main/asciidoc/metrics_spec.adoc#315-timer-json-format) (minutes in this case, nanoseconds is the default if unspecified) whereas Prometheus should always use seconds (https://github.com/eclipse/microprofile-metrics/blob/1.1/spec/src/main/asciidoc/metrics_spec.adoc#328-timer-prometheus-text-format).

You see that your example contains "unit":"minutes" which suggests that the JSON output is in minutes, and in Prometheus the line says items_processed_seconds.

My fix changed the behavior so that Prometheus really converts to seconds, before that there was some completely messed up conversion where the time in nanoseconds (which is the unit for internal storage) was divided by 60 and that was then presented as seconds, I think.

If on OpenLiberty, with a timer with unit=minutes, you're getting the same number with JSON and Prometheus output, then I think it's incorrect. If I understand the spec correctly in that JSON output should use the configured unit of the metric, and Prometheus output should always seconds.

If you want then drop by at my desk and we can dive into it :)

[marekkopecky]

Clarification issue: eclipse/microprofile-metrics#320