JVM metrics failing on latest java17 openj9 with the java agent

kroonprins · July 7, 2023, 7:30am

APM Agent language and version: java 1.39.0

Description of the problem including expected versus actual behavior:

When using the latest version of the openj9 docker image for java 17 (bm-semeru-runtimes:open-17-jdk-jammy@sha256:cd1e06810b6cb7c05efd6697135077cbd0801123b24100a9a0c24ffb332c6a8a), the elastic agent logs this error and jvm related metrics are not sent to the apm server:

2023-07-07 07:22:50,395 [elastic-apm-shared] ERROR co.elastic.apm.agent.util.ExecutorUtils - null
java.lang.UnsupportedOperationException: null
	at com.ibm.lang.management.internal.ExtendedThreadMXBeanImpl.getThreadAllocatedBytes(ExtendedThreadMXBeanImpl.java:82) ~[?:?]
	at co.elastic.apm.agent.metrics.builtin.JvmGcMetrics$HotspotAllocationSupplier.get(JvmGcMetrics.java:82) ~[elastic-apm-agent.jar:1.39.0]
	at co.elastic.apm.agent.report.serialize.MetricRegistrySerializer.serializeGauges(MetricRegistrySerializer.java:125) ~[elastic-apm-agent.jar:1.39.0]
	at co.elastic.apm.agent.report.serialize.MetricRegistrySerializer.serialize(MetricRegistrySerializer.java:92) ~[elastic-apm-agent.jar:1.39.0]
	at co.elastic.apm.agent.report.serialize.MetricRegistrySerializer.serialize(MetricRegistrySerializer.java:76) ~[elastic-apm-agent.jar:1.39.0]
	at co.elastic.apm.agent.report.serialize.MetricRegistrySerializer.serialize(MetricRegistrySerializer.java:56) ~[elastic-apm-agent.jar:1.39.0]
	at co.elastic.apm.agent.report.serialize.MetricRegistryReporter.report(MetricRegistryReporter.java:74) ~[elastic-apm-agent.jar:1.39.0]
	at co.elastic.apm.agent.metrics.MetricRegistry.flipPhaseAndReport(MetricRegistry.java:201) ~[elastic-apm-agent.jar:1.39.0]
	at co.elastic.apm.agent.report.serialize.MetricRegistryReporter.run(MetricRegistryReporter.java:59) ~[elastic-apm-agent.jar:1.39.0]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[?:?]
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
	at co.elastic.apm.agent.util.ExecutorUtils$2.run(ExecutorUtils.java:99) [elastic-apm-agent.jar:1.39.0]
	at java.lang.Thread.run(Thread.java:857) [?:?]

Using a previous image, e.g. ibm-semeru-runtimes:open-17-jdk-jammy@sha256:28f0d18fb8a9444cc6f4d34bfd338fe871558bc4454a5ed2c90b44949d5aae03, then this error does not happen en jvm related metrics do get sent to the apm server.

To reproduce (in the example I use a dummy apm server and a dummy spring boot application):

$ docker run --rm -v $(pwd)/work:/work -e ELASTIC_APM_SERVICE_NAME=test -e ELASTIC_APM_SERVICE_VERSION=1 -e ELASTIC_APM_SERVER_URLS=http://example.com -e ELASTIC_APM_ENABLED=true -e ELASTIC_APM_LOG_LEVEL=INFO -e ELASTIC_APM_SECRET_TOKEN=test ibm-semeru-runtimes:open-17-jdk-jammy@sha256:cd1e06810b6cb7c05efd6697135077cbd0801123b24100a9a0c24ffb332c6a8a java -javaagent:/work/elastic-apm-agent.jar -jar /work/demo-0.0.1-SNAPSHOT.jar
2023-07-07 07:24:55,875 [main] INFO  co.elastic.apm.agent.util.JmxUtils - Found JVM-specific OperatingSystemMXBean interface: com.ibm.lang.management.OperatingSystemMXBean
2023-07-07 07:24:55,900 [main] INFO  co.elastic.apm.agent.util.JmxUtils - Found JVM-specific ThreadMXBean interface: com.sun.management.ThreadMXBean
2023-07-07 07:24:55,909 [main] INFO  co.elastic.apm.agent.configuration.StartupInfo - Starting Elastic APM 1.39.0 as test (1) on Java 17.0.7 Runtime version: 17.0.7+7 VM version: openj9-0.38.0 (IBM Corporation) Linux 5.15.0-75-generic
2023-07-07 07:24:55,910 [main] INFO  co.elastic.apm.agent.configuration.StartupInfo - service_name: 'test' (source: Environment Variables)
2023-07-07 07:24:55,910 [main] INFO  co.elastic.apm.agent.configuration.StartupInfo - service_version: '1' (source: Environment Variables)
2023-07-07 07:24:55,910 [main] INFO  co.elastic.apm.agent.configuration.StartupInfo - secret_token: 'XXXX' (source: Environment Variables)
2023-07-07 07:24:55,910 [main] INFO  co.elastic.apm.agent.configuration.StartupInfo - server_urls: 'http://example.com' (source: Environment Variables)
2023-07-07 07:24:55,910 [main] WARN  co.elastic.apm.agent.configuration.StartupInfo - To enable all features and decrease startup time, please configure application_packages
2023-07-07 07:24:56,186 [main] INFO  co.elastic.apm.agent.bci.ElasticApmAgent - Overriding IndyBootstrapDispatcher class's module to java.base module. This is required in J9 VMs.
2023-07-07 07:24:56,189 [main] INFO  co.elastic.apm.agent.bci.ElasticApmAgent - Overriding IndyBootstrapDispatcher class's module to java.base module. This is required in J9 VMs.
2023-07-07 07:24:56,978 [main] INFO  co.elastic.apm.agent.impl.ElasticApmTracer - Tracer switched to RUNNING state
2023-07-07 07:24:57,354 [elastic-apm-server-healthcheck] INFO  co.elastic.apm.agent.report.ApmServerHealthChecker - Elastic APM server is available: <!doctype html><html><head>    <title>Example Domain</title>    <meta charset="utf-8" />    <meta http-equiv="Content-type" content="text/html; charset=utf-8" />    <meta name="viewport" content="width=device-width, initial-scale=1" />    <style type="text/css">    body {        background-color: #f0f0f2;        margin: 0;        padding: 0;        font-family: -apple-system, system-ui, BlinkMacSystemFont, "Segoe UI", "Open Sans", "Helvetica Neue", Helvetica, Arial, sans-serif;            }    div {        width: 600px;        margin: 5em auto;        padding: 2em;        background-color: #fdfdff;        border-radius: 0.5em;        box-shadow: 2px 3px 7px 2px rgba(0,0,0,0.02);    }    a:link, a:visited {        color: #38488f;        text-decoration: none;    }    @media (max-width: 700px) {        div {            margin: 0 auto;            width: auto;        }    }    </style>    </head><body><div>    <h1>Example Domain</h1>    <p>This domain is for use in illustrative examples in documents. You may use this    domain in literature without prior coordination or asking for permission.</p>    <p><a href="https://www.iana.org/domains/example">More information...</a></p></div></body></html>
2023-07-07 07:24:57,356 [elastic-apm-server-healthcheck] WARN  co.elastic.apm.agent.report.ApmServerHealthChecker - Failed to parse version of APM server http://example.com/: Expecting '{' as object start. Found < at position: 1, following: `<`

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::                (v3.1.1)

2023-07-07T07:24:57.939Z  INFO 1 --- [           main] com.example.demo.DemoApplication         : Starting DemoApplication v0.0.1-SNAPSHOT using Java 17.0.7 with PID 1 (/work/demo-0.0.1-SNAPSHOT.jar started by root in /)
2023-07-07T07:24:57.946Z  INFO 1 --- [           main] com.example.demo.DemoApplication         : No active profile set, falling back to 1 default profile: "default"
2023-07-07T07:24:59.128Z  INFO 1 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2023-07-07T07:24:59.139Z  INFO 1 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2023-07-07T07:24:59.139Z  INFO 1 --- [           main] o.apache.catalina.core.StandardEngine    : Starting Servlet engine: [Apache Tomcat/10.1.10]
2023-07-07T07:24:59.240Z  INFO 1 --- [           main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2023-07-07T07:24:59.242Z  INFO 1 --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 1210 ms
2023-07-07T07:24:59.747Z  INFO 1 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2023-07-07T07:24:59.756Z  INFO 1 --- [           main] com.example.demo.DemoApplication         : Started DemoApplication in 2.393 seconds (process running for 4.307)
2023-07-07 07:25:26,979 [elastic-apm-shared] ERROR co.elastic.apm.agent.util.ExecutorUtils - null
java.lang.UnsupportedOperationException: null
	at com.ibm.lang.management.internal.ExtendedThreadMXBeanImpl.getThreadAllocatedBytes(ExtendedThreadMXBeanImpl.java:82) ~[?:?]
	at co.elastic.apm.agent.metrics.builtin.JvmGcMetrics$HotspotAllocationSupplier.get(JvmGcMetrics.java:82) ~[elastic-apm-agent.jar:1.39.0]
	at co.elastic.apm.agent.report.serialize.MetricRegistrySerializer.serializeGauges(MetricRegistrySerializer.java:125) ~[elastic-apm-agent.jar:1.39.0]
	at co.elastic.apm.agent.report.serialize.MetricRegistrySerializer.serialize(MetricRegistrySerializer.java:92) ~[elastic-apm-agent.jar:1.39.0]
	at co.elastic.apm.agent.report.serialize.MetricRegistrySerializer.serialize(MetricRegistrySerializer.java:76) ~[elastic-apm-agent.jar:1.39.0]
	at co.elastic.apm.agent.report.serialize.MetricRegistrySerializer.serialize(MetricRegistrySerializer.java:56) ~[elastic-apm-agent.jar:1.39.0]
	at co.elastic.apm.agent.report.serialize.MetricRegistryReporter.report(MetricRegistryReporter.java:74) ~[elastic-apm-agent.jar:1.39.0]
	at co.elastic.apm.agent.metrics.MetricRegistry.flipPhaseAndReport(MetricRegistry.java:201) ~[elastic-apm-agent.jar:1.39.0]
	at co.elastic.apm.agent.report.serialize.MetricRegistryReporter.run(MetricRegistryReporter.java:59) ~[elastic-apm-agent.jar:1.39.0]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[?:?]
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
	at co.elastic.apm.agent.util.ExecutorUtils$2.run(ExecutorUtils.java:99) [elastic-apm-agent.jar:1.39.0]
	at java.lang.Thread.run(Thread.java:857) [?:?]

With the a previous image:

2023-07-07 07:26:56,907 [main] INFO  co.elastic.apm.agent.util.JmxUtils - Found JVM-specific OperatingSystemMXBean interface: com.ibm.lang.management.OperatingSystemMXBean
2023-07-07 07:26:56,953 [main] INFO  co.elastic.apm.agent.configuration.StartupInfo - Starting Elastic APM 1.39.0 as test (1) on Java 17.0.6 Runtime version: 17.0.6+10 VM version: openj9-0.36.0 (IBM Corporation) Linux 5.15.0-75-generic
2023-07-07 07:26:56,954 [main] INFO  co.elastic.apm.agent.configuration.StartupInfo - service_name: 'test' (source: Environment Variables)
2023-07-07 07:26:56,954 [main] INFO  co.elastic.apm.agent.configuration.StartupInfo - service_version: '1' (source: Environment Variables)
2023-07-07 07:26:56,954 [main] INFO  co.elastic.apm.agent.configuration.StartupInfo - secret_token: 'XXXX' (source: Environment Variables)
2023-07-07 07:26:56,954 [main] INFO  co.elastic.apm.agent.configuration.StartupInfo - server_urls: 'http://example.com' (source: Environment Variables)
2023-07-07 07:26:56,954 [main] WARN  co.elastic.apm.agent.configuration.StartupInfo - To enable all features and decrease startup time, please configure application_packages
2023-07-07 07:26:57,213 [main] INFO  co.elastic.apm.agent.bci.ElasticApmAgent - Overriding IndyBootstrapDispatcher class's module to java.base module. This is required in J9 VMs.
2023-07-07 07:26:57,216 [main] INFO  co.elastic.apm.agent.bci.ElasticApmAgent - Overriding IndyBootstrapDispatcher class's module to java.base module. This is required in J9 VMs.
2023-07-07 07:26:58,072 [main] INFO  co.elastic.apm.agent.impl.ElasticApmTracer - Tracer switched to RUNNING state
2023-07-07 07:26:58,444 [elastic-apm-server-healthcheck] INFO  co.elastic.apm.agent.report.ApmServerHealthChecker - Elastic APM server is available: <!doctype html><html><head>    <title>Example Domain</title>    <meta charset="utf-8" />    <meta http-equiv="Content-type" content="text/html; charset=utf-8" />    <meta name="viewport" content="width=device-width, initial-scale=1" />    <style type="text/css">    body {        background-color: #f0f0f2;        margin: 0;        padding: 0;        font-family: -apple-system, system-ui, BlinkMacSystemFont, "Segoe UI", "Open Sans", "Helvetica Neue", Helvetica, Arial, sans-serif;            }    div {        width: 600px;        margin: 5em auto;        padding: 2em;        background-color: #fdfdff;        border-radius: 0.5em;        box-shadow: 2px 3px 7px 2px rgba(0,0,0,0.02);    }    a:link, a:visited {        color: #38488f;        text-decoration: none;    }    @media (max-width: 700px) {        div {            margin: 0 auto;            width: auto;        }    }    </style>    </head><body><div>    <h1>Example Domain</h1>    <p>This domain is for use in illustrative examples in documents. You may use this    domain in literature without prior coordination or asking for permission.</p>    <p><a href="https://www.iana.org/domains/example">More information...</a></p></div></body></html>
2023-07-07 07:26:58,447 [elastic-apm-server-healthcheck] WARN  co.elastic.apm.agent.report.ApmServerHealthChecker - Failed to parse version of APM server http://example.com/: Expecting '{' as object start. Found < at position: 1, following: `<`

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::                (v3.1.1)

2023-07-07T07:26:59.057Z  INFO 1 --- [           main] com.example.demo.DemoApplication         : Starting DemoApplication v0.0.1-SNAPSHOT using Java 17.0.6 with PID 1 (/work/demo-0.0.1-SNAPSHOT.jar started by root in /)
2023-07-07T07:26:59.067Z  INFO 1 --- [           main] com.example.demo.DemoApplication         : No active profile set, falling back to 1 default profile: "default"
2023-07-07T07:27:00.136Z  INFO 1 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2023-07-07T07:27:00.149Z  INFO 1 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2023-07-07T07:27:00.149Z  INFO 1 --- [           main] o.apache.catalina.core.StandardEngine    : Starting Servlet engine: [Apache Tomcat/10.1.10]
2023-07-07T07:27:00.221Z  INFO 1 --- [           main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2023-07-07T07:27:00.222Z  INFO 1 --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 1090 ms
2023-07-07T07:27:00.722Z  INFO 1 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2023-07-07T07:27:00.735Z  INFO 1 --- [           main] com.example.demo.DemoApplication         : Started DemoApplication in 2.272 seconds (process running for 4.254)
2023-07-07 07:27:38,749 [elastic-apm-server-reporter] WARN  co.elastic.apm.agent.report.AbstractIntakeApiHandler - Response body: <?xml version="1.0" encoding="iso-8859-1"?>
<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN"
         "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">
<html xmlns="http://www.w3.org/1999/xhtml" xml:lang="en" lang="en">
	<head>
		<title>404 - Not Found</title>
	</head>
	<body>
		<h1>404 - Not Found</h1>
		<script type="text/javascript" src="//obj.ac.bcon.ecdns.net/ec_tpm_bcon.js"></script>
	</body>
</html>

Any idea if this is an issue with the agent or if something needs to be raised with openj9?

Sylvain_Juge · July 7, 2023, 7:53am

Hi !

Thanks for reporting this, this is definitely a bug in the agent, it seems the newer JVM does not support this way of collecting the JVM metrics (the agent has to rely on a few implementation details that might have changed between the two versions).

I have opened this issue to track and solve this.

In the mean time could you stick to the previous version as a work-around ?

kroonprins · July 7, 2023, 8:24am

Thanks for the quick reply!
Yes, we can keep using the previous version for now. We do try to keep this image as updated as possible for security fixes, so it wouldn't be ideal to do this for a significant time.

Sylvain_Juge · July 7, 2023, 3:36pm

I've managed to reproduce and fix it with this PR, if you want to try a snapshot version should be available in a few minutes once the build had completed in build artifacts here: Ignore gc alloc metrics when unsupported · elastic/apm-agent-java@43998c5 · GitHub

kroonprins · July 7, 2023, 4:02pm

great, I'll give it a try once the pipeline completes (seems to be running for over an hour already )

kroonprins · July 7, 2023, 4:41pm

works for me . No more error and apm server receives jvm metrics.

system · August 4, 2023, 4:42pm

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.

Topic		Replies	Views
NPE using APM Agent 1.33.0 APM docker , java	5	610	September 16, 2022
Bug: APM Java - Springboot, v1.39.0+ - No JVM Metrics Found APM java	14	684	September 5, 2023
JVM crashes with APM agent 1.33 and JPMS enabled APM java	5	430	August 3, 2022
Error with Java APM agent on kubernetes: Failed to handle event of type METRICS with this error: / by zero APM java	3	444	August 3, 2020
JVM corrupted with java agent 1.19.0 - CentOS APM java	7	686	December 27, 2020

JVM metrics failing on latest java17 openj9 with the java agent

Related topics