Opentelemetry java agent not producing http_server_request_duration_seconds and http_client_request_duration_seconds on ARM architecture, Linux or Macbook with M series chipset

[deepaksrivastavaz]

Describe the bug

I have configured a web application in Tomcat 9.0.14 with Java 8 Corretto along with otel java agent 2.4.0. It is not producing below metrics
http_server_request_duration_seconds_{count|sum|bucket}
http_client_request_duration_seconds_{count|sum|bucket}

whereas it used to work on an Intel machine, i.e. x86 architecture on Linux as well as MacOs.

Interestingly other metrics are being produced for the app, ex: db_client_connections_usage, db_client_connections_pending_requests, jvm_class_count, target_info etc along with http_server_active_requests when -Dotel.instrumentation.http.server.emit-experimental-telemetry=true is set.

I also tried launching a bare minumium Tomcat 10.1.31 along with Eclipse Temurin build on MacOs but it's still not producing the http_server* or http_client_* metrics.

./java -version
openjdk version "11.0.25" 2024-10-15
OpenJDK Runtime Environment Temurin-11.0.25+9 (build 11.0.25+9)
OpenJDK 64-Bit Server VM Temurin-11.0.25+9 (build 11.0.25+9, mixed mode)

Steps to reproduce

Pick a setup deployed with config

1. Java 8 distro

openjdk version "1.8.0_422"
OpenJDK Runtime Environment Corretto-8.422.05.1 (build 1.8.0_422-b05)
OpenJDK 64-Bit Server VM Corretto-8.422.05.1 (build 25.422-b05, mixed mode)

2. Tomcat 9.0.14
3. A basic webapp deployed in it to recieve requests on http or even the Tomcat default works, i.e.; /examples.

Expected behavior

As on Intel or x86 architecture it should produce http_server_* and http_client_* metrics seamlessly.

Actual behavior

Not producing http_server_* and http_client_* metrics seamlessly on ARM architecture.

Javaagent or library instrumentation version

2.4.0, 2.6.0, 2.9.0

Environment

JDK: Temurin 11.0.25, OpenJDK Runtime Environment Corretto-8.422.05.1 (build 1.8.0_422-b05)
OS: Amazon Linux 2023, MacOs

Additional context

No response

[laurit]

Please provide a minimal application that reproduces the issue along with any necessary instructions.

[deepaksrivastavaz]

apache-tomcat-9.0.14.zip

Hi @laurit, I tried to dig a little further into the situation (explained in Observations section below) and here is a minimal tomcat setup attached.

About app (zip attachment)

1. Will refer java from standard JAVA_HOME env variable from the machine, not explicitly set in catalina.sh.
2. opentelemetry-javaagent-2.4.0.jar isn't attached in zip due to upload size limitations. Should be downloaded from https://github.com/open-telemetry/opentelemetry-java-instrumentation/releases/download/v2.4.0/opentelemetry-javaagent.jar and put in root folder, i.e.; apache-tomcat-9.0.14/
3. apache-tomcat-9.0.14/logs/catalina.out is also in the zip for detailed info on env vars etc.

Pre-requisites

1. Java 8 need to be available locally or other set JAVA_HOME before starting or set it in catalina.sh on Line#119. I am using amazon-corretto-8.jdk (1.8.0_422-b05) on Mac OS X 15.0.1 with aarch64 architecture.
2. Once Tomcat is up & running you can use http://localhost:8080/examples/jsp/sessions/carts.jsp?item=Beavis+%26+Butt-head+Video+collection&submit=remove to add/remove entries which'll produce the http.server.request.duration metric.

Observations

1. After setting the -Dotel.metrics.exporter=otlp,console I can see this specific log being printed in catalina.out which is a clear indicator that http.server.request.duration is being considered by PeriodicMetricReader
   [otel.javaagent 2024-10-28 20:34:39:003 +0530] [PeriodicMetricReader-1] INFO io.opentelemetry.exporter.logging.LoggingMetricExporter - metric: ImmutableMetricData{resource=Resource{schemaUrl=https://opentelemetry.io/schemas/1.24.0, attributes={commit.id="ba898d9", env="local", host.arch="aarch64", host.name="IN-DEL-D39RYWC72V", os.description="Mac OS X 15.0.1", os.type="darwin", process.command_line="/Library/Java/JavaVirtualMachines/amazon-corretto-8.jdk/Contents/Home/jre/bin/java -Djava.util.logging.config.file=/Users/Deepak/Downloads/Github OTel Java Agent/apache-tomcat-9.0.14/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Djdk.tls.ephemeralDHKeySize=2048 -javaagent:./../opentelemetry-javaagent-2.4.0.jar -Dotel.instrumentation.http.server.emit-experimental-telemetry=true -Dotel.sdk.disabled=false -Dotel.javaagent.enabled=true -Dotel.javaagent.debug=false -Dotel.metrics.exporter=otlp,console -Dotel.logs.exporter=none -Dotel.traces.exporter=none -Dotel.exporter.otlp.compression=gzip -Dotel.resource.attributes=service.instance.id=instance_1,service.version=1.2.3,commit.id=ba898d9,env=local -Dotel.service.name=test-service-101-with-http-metrics-issue -Dotel.exporter.otlp.protocol=grpc -Dotel.exporter.otlp.metrics.default.histogram.aggregation=base2_exponential_bucket_histogram -Djava.protocol.handler.pkgs=org.apache.catalina.webresources -Dotel.exporter.otlp.endpoint=http://localhost:4317 -Dorg.apache.catalina.security.SecurityListener.UMASK=0027 -Dignore.endorsed.dirs= -Dcatalina.base=/Users/Deepak/Downloads/Github OTel Java Agent/apache-tomcat-9.0.14 -Dcatalina.home=/Users/Deepak/Downloads/Github OTel Java Agent/apache-tomcat-9.0.14 -Djava.io.tmpdir=/Users/Deepak/Downloads/Github OTel Java Agent/apache-tomcat-9.0.14/temp org.apache.catalina.startup.Bootstrap start", process.executable.path="/Library/Java/JavaVirtualMachines/amazon-corretto-8.jdk/Contents/Home/jre/bin/java", process.pid=94462, process.runtime.description="Amazon.com Inc. OpenJDK 64-Bit Server VM 25.422-b05", process.runtime.name="OpenJDK Runtime Environment", process.runtime.version="1.8.0_422-b05", service.instance.id="instance_1", service.name="test-service-101-with-http-metrics-issue", service.version="1.2.3", telemetry.distro.name="opentelemetry-java-instrumentation", telemetry.distro.version="2.4.0", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.38.0"}}, instrumentationScopeInfo=InstrumentationScopeInfo{name=io.opentelemetry.tomcat-7.0, version=2.4.0-alpha, schemaUrl=null, attributes={}}, name=http.server.request.duration, description=Duration of HTTP server requests., unit=s, type=HISTOGRAM, data=ImmutableHistogramData{aggregationTemporality=CUMULATIVE, points=[ImmutableHistogramPointData{getStartEpochNanos=1730127818961000000, getEpochNanos=1730127878968000000, getAttributes={http.request.method="GET", http.response.status_code=200, http.route="/*", network.protocol.version="1.1", url.scheme="http"}, getSum=0.012524126, getCount=4, hasMin=true, getMin=0.001253917, hasMax=true, getMax=0.006885292, getBoundaries=[0.005, 0.01, 0.025, 0.05, 0.075, 0.1, 0.25, 0.5, 0.75, 1.0, 2.5, 5.0, 7.5, 10.0], getCounts=[3, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0], getExemplars=[ImmutableDoubleExemplarData{filteredAttributes={client.address="0:0:0:0:0:0:0:1", http.response.body.size=21630, network.peer.address="0:0:0:0:0:0:0:1", network.peer.port=62093, server.address="localhost", server.port=8080, url.path="/favicon.ico", user_agent.original="Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/130.0.0.0 Safari/537.36"}, epochNanos=1730127835395000000, spanContext=ImmutableSpanContext{traceId=4895de1b4612f663706fd8a4590d319b, spanId=6407f01496bc8f4f, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, value=0.002731417}, ImmutableDoubleExemplarData{filteredAttributes={client.address="0:0:0:0:0:0:0:1", http.response.body.size=21630, network.peer.address="0:0:0:0:0:0:0:1", network.peer.port=62089, server.address="localhost", server.port=8080, url.path="/favicon.ico", user_agent.original="Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/130.0.0.0 Safari/537.36"}, epochNanos=1730127827353000000, spanContext=ImmutableSpanContext{traceId=370e045b9afaa4372c573a1e75152d1f, spanId=d0c31c12ad074031, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, value=0.006885292}]}, ImmutableHistogramPointData{getStartEpochNanos=1730127818961000000, getEpochNanos=1730127878968000000, getAttributes={http.request.method="GET", http.response.status_code=200, http.route="/examples/jsp/sessions/carts.jsp", network.protocol.version="1.1", url.scheme="http"}, getSum=0.10355804100000002, getCount=7, hasMin=true, getMin=0.002252209, hasMax=true, getMax=0.083056792, getBoundaries=[0.005, 0.01, 0.025, 0.05, 0.075, 0.1, 0.25, 0.5, 0.75, 1.0, 2.5, 5.0, 7.5, 10.0], getCounts=[5, 1, 0, 0, 0, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0], getExemplars=[ImmutableDoubleExemplarData{filteredAttributes={client.address="0:0:0:0:0:0:0:1", http.response.body.size=1677, network.peer.address="0:0:0:0:0:0:0:1", network.peer.port=62093, server.address="localhost", server.port=8080, url.path="/examples/jsp/sessions/carts.jsp", url.query="item=Beavis+%26+Butt-head+Video+collection&submit=remove", user_agent.original="Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/130.0.0.0 Safari/537.36"}, epochNanos=1730127835234000000, spanContext=ImmutableSpanContext{traceId=41b869497d18046f1fbb9c906255d534, spanId=f9a747a0b6ce179d, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, value=0.002320916}, ImmutableDoubleExemplarData{filteredAttributes={client.address="0:0:0:0:0:0:0:1", http.response.body.size=1677, network.peer.address="0:0:0:0:0:0:0:1", network.peer.port=62091, server.address="localhost", server.port=8080, url.path="/examples/jsp/sessions/carts.jsp", url.query="item=Rex%2C+Rugs+%26+Rock+n%27+Roll&submit=add", user_agent.original="Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/130.0.0.0 Safari/537.36"}, epochNanos=1730127831313000000, spanContext=ImmutableSpanContext{traceId=13ab14b48cf6ceaf52cfa60f3b56ffd0, spanId=478cd96385214107, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, value=0.005533041}, ImmutableDoubleExemplarData{filteredAttributes={client.address="0:0:0:0:0:0:0:1", http.response.body.size=1598, network.peer.address="0:0:0:0:0:0:0:1", network.peer.port=62089, server.address="localhost", server.port=8080, url.path="/examples/jsp/sessions/carts.jsp", url.query="item=Switch+blade&submit=add", user_agent.original="Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/130.0.0.0 Safari/537.36"}, epochNanos=1730127827205000000, spanContext=ImmutableSpanContext{traceId=c8eba5aa45d95462b7ae89f240258440, spanId=93a4b4ea003f6f0d, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, value=0.083056792}]}]}}
2. I have setup Grafana Alloy locally just to eliminate any potential issue and don't see any drop of this specific metric for any reason in alloy logs.
3. In Grafana I see other metrics, example experimental http_server_active_requests or jvm_* which tells the telemetry data flow pipeline is working properly and the issue is for some reason restricted to specific http_server_request_duration_,http_client_request_duration_
   

NOTE: I am not focusing on http_client_request_duration_* right now given that once http_server_request_duration_* gets solved the client metric is likely problematic because of the same reason.

Also as mentioned in opening comment I tried the same with Temurin 11.0.25 and Tomcat 10.1.31 on the same MacOS and the behavior is same. Also using agent 2.4.0, 2.6.0 and 2.9.0 produces the same output.

Let me know if more details are required.

Thanks in advance.

[laurit]

As you see the http.server.request.duration metric in the console logger output have you considered that the problem is not in agent but in something else, like your metics backend? The first thing I'd try would be to remove -Dotel.exporter.otlp.metrics.default.histogram.aggregation=base2_exponential_bucket_histogram. Perhaps your backend does not support exponential histograms. You could also try sending the data to a collector configured with verbose logging, that way you can verify that the http.server.request.duration is sent by the agent.

[deepaksrivastavaz]

Thanks much @laurit . This has really helped, somehow during a transition this -Dotel.exporter.otlp.metrics.default.histogram.aggregation=base2_exponential_bucket_histogram. got added along the way and due to various other variables (hardware+software) this went unnoticed.

Now this is working as expected with the corretto and ARM architecture. Need to see on Grafana Mimir side to understand what to do to enable this support. Thanks a lot.