Exported Prometheus Duration Incorrect by Factor 1,000,000

[kolloch]

Expected Behavior

I wrote a little sample program, the whole source is here: https://github.com/kolloch/debug-opentelemetry-poem

use std::time::Duration;

use eyre::Context;
use opentelemetry::sdk::{metrics::{controllers, processors, selectors}, export::metrics::aggregation};
use poem::{Server, listener::TcpListener, Route, get, EndpointExt, middleware::OpenTelemetryMetrics, handler, web::Path, endpoint::PrometheusExporter};
use tokio::time::sleep;


#[tokio::main]
async fn main() -> color_eyre::Result<()> {
    let prometheus_controller = controllers::basic(
        processors::factory(
            selectors::simple::histogram([1.0, 2.0, 5.0, 10.0, 20.0, 50.0, 70.0, 100.0, 200.0, 300.0, 400.0, 500.0, 700.0, 1000.0, 1500.0, 3000.0]),
            aggregation::cumulative_temporality_selector(),
        )
        .with_memory(true),
    )
    .build();

    println!("Starting server at localhost:8080");
    Server::new(TcpListener::bind("localhost:8080"))
            .run(
                Route::new()
                    .at("/hello/:name", get(hello))
                    .nest("/prometheus_metrics", PrometheusExporter::with_controller(prometheus_controller))
                    .with(OpenTelemetryMetrics::new()))

            .await
            .context("while running public API")?;

    Ok(())
}

#[handler]
async fn hello(Path(name): Path<String>) -> String {
    sleep(Duration::from_millis(100)).await;
    format!("hello: {}", name)
}

If I perform some requests, e.g. by reloading http://localhost:8080/hello/program a couple of times. I expect plausible values for poem_request_duration_ms_bucket in http://localhost:8080/prometheus_metrics afterwards.

That means that all requests should take at least 100 ms -- because of the sleep.

Actual Behavior

Instead, the counters for all buckets in the

# HELP poem_request_duration_ms request duration histogram (in milliseconds, since start of service)
# TYPE poem_request_duration_ms histogram
poem_request_duration_ms_bucket{http_method="GET",http_status_code="200",http_url="/hello/program",service_name="unknown_service",le="1"} 11
poem_request_duration_ms_bucket{http_method="GET",http_status_code="200",http_url="/hello/program",service_name="unknown_service",le="2"} 11
poem_request_duration_ms_bucket{http_method="GET",http_status_code="200",http_url="/hello/program",service_name="unknown_service",le="5"} 11
poem_request_duration_ms_bucket{http_method="GET",http_status_code="200",http_url="/hello/program",service_name="unknown_service",le="10"} 11
poem_request_duration_ms_bucket{http_method="GET",http_status_code="200",http_url="/hello/program",service_name="unknown_service",le="20"} 11
poem_request_duration_ms_bucket{http_method="GET",http_status_code="200",http_url="/hello/program",service_name="unknown_service",le="50"} 11
poem_request_duration_ms_bucket{http_method="GET",http_status_code="200",http_url="/hello/program",service_name="unknown_service",le="70"} 11
poem_request_duration_ms_bucket{http_method="GET",http_status_code="200",http_url="/hello/program",service_name="unknown_service",le="100"} 11
poem_request_duration_ms_bucket{http_method="GET",http_status_code="200",http_url="/hello/program",service_name="unknown_service",le="200"} 11
poem_request_duration_ms_bucket{http_method="GET",http_status_code="200",http_url="/hello/program",service_name="unknown_service",le="300"} 11
poem_request_duration_ms_bucket{http_method="GET",http_status_code="200",http_url="/hello/program",service_name="unknown_service",le="400"} 11
poem_request_duration_ms_bucket{http_method="GET",http_status_code="200",http_url="/hello/program",service_name="unknown_service",le="500"} 11
poem_request_duration_ms_bucket{http_method="GET",http_status_code="200",http_url="/hello/program",service_name="unknown_service",le="700"} 11
poem_request_duration_ms_bucket{http_method="GET",http_status_code="200",http_url="/hello/program",service_name="unknown_service",le="1000"} 11
poem_request_duration_ms_bucket{http_method="GET",http_status_code="200",http_url="/hello/program",service_name="unknown_service",le="1500"} 11
poem_request_duration_ms_bucket{http_method="GET",http_status_code="200",http_url="/hello/program",service_name="unknown_service",le="3000"} 11
poem_request_duration_ms_bucket{http_method="GET",http_status_code="200",http_url="/hello/program",service_name="unknown_service",le="+Inf"} 11
poem_request_duration_ms_sum{http_method="GET",http_status_code="200",http_url="/hello/program",service_name="unknown_service"} 0.001111163905
poem_request_duration_ms_count{http_method="GET",http_status_code="200",http_url="/hello/program",service_name="unknown_service"} 11
# HELP poem_requests_count total request count (since start of service)
# TYPE poem_requests_count counter
poem_requests_count{http_method="GET",http_status_code="200",http_url="/hello/program",service_name="unknown_service"} 11

Steps to Reproduce the Problem

1. Get code at https://github.com/kolloch/debug-opentelemetry-poem
2. Execute cargo run
3. Reload http://localhost:8080/hello/program a couple of times in the browser
4. Look at http://localhost:8080/prometheus_metrics

Specifications

• Version: "poem" "1.3.50", for other versions see https://github.com/kolloch/debug-opentelemetry-poem/blob/main/Cargo.lock
• Platform: Linux i64
• Subsystem: feature flags opentelemetry / prometheus

Thanks a lot!

[kolloch]

I added a test showing that the underlying libraries should be fine: https://github.com/kolloch/debug-opentelemetry-poem/blob/main/tests/correct_metric_values.rs

(basically, it is a stripped down version of the code that poem uses here)