Bug: APM Java - Springboot, v1.39.0+ - No JVM Metrics Found

6fears7 · July 24, 2023, 1:47pm

After reviewing the following post and appropriate GitHub issue, utilizing the Java APM agent on versions 1.39.0+ (including 1.40.0), JVM Metrics fail to display in the Metrics tab of APM. Below is an example of me swapping the agent versions to show the drop-off:

After reviewing APM log levels, no error logs are thrown, and debug logs are very verbose, making tacking this source issue down difficult. I can post debug logs on request.

Versions:
Java -
openjdk version "11.0.19" 2023-04-18
OpenJDK Runtime Environment (build 11.0.19+7-post-Ubuntu-0ubuntu122.04.1)
Springboot versions: 2.5.1, 3.x.x
OpenJDK 64-Bit Server VM (build 11.0.19+7-post-Ubuntu-0ubuntu122.04.1, mixed mode, sharing)

APM -
1.39.0, 1.40.0

Jonas_Kunz · July 25, 2023, 9:28am

Unfortunately we will need the debug-level agent logs here to help you further. You can use GitHub Gists to upload the logs.

I think the linked issue should be unrelated, as it is specific to IBM Semeru JDK17.

6fears7 · July 25, 2023, 12:22pm

Great, here you go:

gist.github.com

https://gist.github.com/6fears7/f97d814e1745dbd40f2693ace674304c

gistfile1.txt

2023-07-25 08:44:41,381 [Attach Listener] DEBUG co.elastic.apm.agent.util.ExecutorUtils - A new thread named `elastic-apm-configuration-reloader` was created. The original context class loader of this thread (null) has been overridden
2023-07-25 08:44:41,393 [Attach Listener] DEBUG co.elastic.apm.agent.util.ExecutorUtils - A new thread named `elastic-apm-metadata-0` was created. The original context class loader of this thread (null) has been overridden
2023-07-25 08:44:41,393 [Attach Listener] DEBUG co.elastic.apm.agent.util.ExecutorUtils - A new thread named `elastic-apm-metadata-1` was created. The original context class loader of this thread (null) has been overridden
2023-07-25 08:44:41,394 [elastic-apm-metadata-1] DEBUG co.elastic.apm.agent.util.ExecutorUtils - A new thread named `elastic-apm-cloud-metadata-0` was created. The original context class loader of this thread (ShadedClassLoader{parent=ShadedClassLoader{parent=jdk.internal.loader.ClassLoaders$PlatformClassLoader@13b518ad, customPrefix='cached-lookup-key/', manifest=java.util.jar.Manifest@23564564, jarUrl=file:/tmp/elastic-apm-agent-69c0d2416d173ba6e1c841b566fa4ca3-e6256b9ad98d9992211305097d439d61.jar}, customPrefix='agent/', manifest=java.util.jar.Manifest@23564564, jarUrl=file:/tmp/elastic-apm-agent-69c0d2416d173ba6e1c841b566fa4ca3-e6256b9ad98d9992211305097d439d61.jar}) has been overridden
2023-07-25 08:44:41,395 [elastic-apm-metadata-1] DEBUG co.elastic.apm.agent.util.ExecutorUtils - A new thread named `elastic-apm-cloud-metadata-1` was created. The original context class loader of this thread (ShadedClassLoader{parent=ShadedClassLoader{parent=jdk.internal.loader.ClassLoaders$PlatformClassLoader@13b518ad, customPrefix='cached-lookup-key/', manifest=java.util.jar.Manifest@23564564, jarUrl=file:/tmp/elastic-apm-agent-69c0d2416d173ba6e1c841b566fa4ca3-e6256b9ad98d9992211305097d439d61.jar}, customPrefix='agent/', manifest=java.util.jar.Manifest@23564564, jarUrl=file:/tmp/elastic-apm-agent-69c0d2416d173ba6e1c841b566fa4ca3-e6256b9ad98d9992211305097d439d61.jar}) has been overridden
2023-07-25 08:44:41,397 [elastic-apm-cloud-metadata-0] DEBUG co.elastic.apm.agent.util.UrlConnectionUtils - Opening http://169.254.169.254/latest/api/token without proxy
2023-07-25 08:44:41,399 [elastic-apm-metadata-1] DEBUG co.elastic.apm.agent.util.UrlConnectionUtils - Opening http://169.254.169.254/metadata/instance/compute?api-version=2019-08-15 without proxy
2023-07-25 08:44:41,399 [elastic-apm-cloud-metadata-1] DEBUG co.elastic.apm.agent.util.UrlConnectionUtils - Opening http://metadata.google.internal/computeMetadata/v1/?recursive=true without proxy
2023-07-25 08:44:41,412 [Attach Listener] INFO  co.elastic.apm.agent.util.JmxUtils - Found JVM-specific OperatingSystemMXBean interface: com.sun.management.OperatingSystemMXBean
2023-07-25 08:44:41,415 [Attach Listener] DEBUG co.elastic.apm.agent.metrics.builtin.CGroupMetrics - max cgroup memory read from /sys/fs/cgroup/user.slice/user-1000.slice/user@1000.service/app.slice/snap.code.code.cd389d20-cf2d-4560-b3a6-72012270a5ca.scope/memory.max is: max

This file has been truncated. show original

Jonas_Kunz · July 26, 2023, 7:52am

The logs indicate that metrics are actually being sent:

2023-07-25 08:45:06,685 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving METRICSET_JSON_WRITER event (sequence 1)
2023-07-25 08:45:06,685 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving METRICSET_JSON_WRITER event (sequence 2)
2023-07-25 08:45:06,685 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving METRICSET_JSON_WRITER event (sequence 3)
2023-07-25 08:45:06,685 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving METRICSET_JSON_WRITER event (sequence 4)
2023-07-25 08:45:06,685 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving METRICSET_JSON_WRITER event (sequence 5)
2023-07-25 08:45:06,686 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving METRICSET_JSON_WRITER event (sequence 6)
2023-07-25 08:45:06,686 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving METRICSET_JSON_WRITER event (sequence 7)
2023-07-25 08:45:06,686 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving METRICSET_JSON_WRITER event (sequence 8)
2023-07-25 08:45:06,686 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving METRICSET_JSON_WRITER event (sequence 9)

To verify that those are actually the JVM metrics and that they make it to elasticsearch please do the following:

Start your application with apm agent 1.39.0 and leave it running for a while
In Kibana got to discover and
- Select a time range of at least a few minutes within which your application was runnign with agent 1.39.0
- Select the APM dataview
- Enter the following filter: service.name:"javaPyro" and processor.event :"metric" and "system.cpu.total.norm.pct" : *

You should then get some documents containing the CPU usage if the metrics made it from the agent to elasticsearch.

6fears7 · July 26, 2023, 12:54pm

Performed the above, there are no docs per the query. I have attached a query searching for any metrics, and then system.cpu docs to show the difference.

6fears7 · July 26, 2023, 12:55pm

Here is the full query's result

6fears7 · July 26, 2023, 1:13pm

Here is a snippet of the server side logs at that time:

gist.github.com

https://gist.github.com/6fears7/352b678ff8944ab476d894b9566bbf28

gistfile1.txt

Jul 26 09:10:30 my-server apm-server[27901]: {"log.level":"error","@timestamp":"2023-07-26T09:10:30.874-0400","log.origin":{"file.name":"go-docappender@v0.1.0/appender.go","file.line":279},"message":"failed to index document (mapper_parsing_exception): Can't find dynamic template for dynamic template name [double] of field [jvm.memory.non_heap.pool.used]","service.name":"apm-server","ecs.version":"1.6.0"}
Jul 26 09:10:30 my-server apm-server[27901]: {"log.level":"error","@timestamp":"2023-07-26T09:10:30.874-0400","log.origin":{"file.name":"go-docappender@v0.1.0/appender.go","file.line":279},"message":"failed to index document (mapper_parsing_exception): Can't find dynamic template for dynamic template name [double] of field [jvm.memory.non_heap.pool.used]","service.name":"apm-server","ecs.version":"1.6.0"}
Jul 26 09:10:30 my-server apm-server[27901]: {"log.level":"error","@timestamp":"2023-07-26T09:10:30.874-0400","log.origin":{"file.name":"go-docappender@v0.1.0/appender.go","file.line":279},"message":"failed to index document (mapper_parsing_exception): Can't find dynamic template for dynamic template name [double] of field [jvm.memory.non_heap.pool.used]","service.name":"apm-server","ecs.version":"1.6.0"}
Jul 26 09:10:30 my-server apm-server[27901]: {"log.level":"error","@timestamp":"2023-07-26T09:10:30.874-0400","log.origin":{"file.name":"go-docappender@v0.1.0/appender.go","file.line":279},"message":"failed to index document (mapper_parsing_exception): Can't find dynamic template for dynamic template name [double] of field [jvm.memory.non_heap.pool.used]","service.name":"apm-server","ecs.version":"1.6.0"}
Jul 26 09:10:30 my-server apm-server[27901]: {"log.level":"error","@timestamp":"2023-07-26T09:10:30.874-0400","log.origin":{"file.name":"go-docappender@v0.1.0/appender.go","file.line":279},"message":"failed to index document (mapper_parsing_exception): Can't find dynamic template for dynamic template name [double] of field [jvm.memory.non_heap.pool.used]","service.name":"apm-server","ecs.version":"1.6.0"}
Jul 26 09:10:31 my-server apm-server[27901]: {"log.level":"error","@timestamp":"2023-07-26T09:10:31.853-0400","log.origin":{"file.name":"go-docappender@v0.1.0/appender.go","file.line":279},"message":"failed to index document (mapper_parsing_exception): Can't find dynamic template for dynamic template name [double] of field [logback_events]","service.name":"apm-server","ecs.version":"1.6.0"}
Jul 26 09:10:31 my-server apm-server[27901]: {"log.level":"error","@timestamp":"2023-07-26T09:10:31.853-0400","log.origin":{"file.name":"go-docappender@v0.1.0/appender.go","file.line":279},"message":"failed to index document (mapper_parsing_exception): Can't find dynamic template for dynamic template name [double] of field [jvm_memory_used]","service.name":"apm-server","ecs.version":"1.6.0"}
Jul 26 09:10:31 my-server apm-server[27901]: {"log.level":"error","@timestamp":"2023-07-26T09:10:31.853-0400","log.origin":{"file.name":"go-docappender@v0.1.0/appender.go","file.line":279},"message":"failed to index document (mapper_parsing_exception): Can't find dynamic template for dynamic template name [double] of field [jvm_threads_states]","service.name":"apm-server","ecs.version":"1.6.0"}
Jul 26 09:10:31 my-server apm-server[27901]: {"log.level":"error","@timestamp":"2023-07-26T09:10:31.853-0400","log.origin":{"file.name":"go-docappender@v0.1.0/appender.go","file.line":279},"message":"failed to index document (mapper_parsing_exception): Can't find dynamic template for dynamic template name [double] of field [jvm_gc_memory_promoted]","service.name":"apm-server","ecs.version":"1.6.0"}
Jul 26 09:10:31 my-server apm-server[27901]: {"log.level":"error","@timestamp":"2023-07-26T09:10:31.853-0400","log.origin":{"file.name":"go-docappender@v0.1.0/appender.go","file.line":279},"message":"failed to index document (mapper_parsing_exception): Can't find dynamic template for dynamic template name [double] of field [lettuce_command_completion.count]","service.name":"apm-server","ecs.version":"1.6.0"}

This file has been truncated. show original

Jonas_Kunz · July 26, 2023, 2:41pm

This seems to be an APM-server issue related to some new JVM metrics which were added in the Java Agent 1.39.0. Which APM-server version are you using?

6fears7 · July 26, 2023, 2:58pm

AM Server Version: 8.7.0

Jonas_Kunz · July 27, 2023, 7:46am

I've been able to reproduce the issue. The newly added JVM metrics are not correctly mapped by pre 8.9.0 APM server versions, causing the metricsets (which include other JVM metrics) to be dropped.

I would suggest you to either

Upgrade your APM-server to 8.9.0
Disable the "bad" metrics in the APM Agent via disable_metrics=jvm.fd.*,jvm.memory.non_heap.pool.*

6fears7 · July 27, 2023, 12:10pm

Awesome, thanks for looking into it Jonas

Jonas_Kunz · July 27, 2023, 3:00pm

Minor clarification: We didn't try reproducing the issue, but came up with an explanation.
Unfortunately that explanation doesn't seem to be valid:
I tried to actually reproduce the behaviour you are seeing with an 8.7.0 deployment and can't reproduce it.

It looks like your deployment of the apm-package is somehow incorrect / corrupted.
Nonetheless disable_metrics=jvm.fd.*,jvm.memory.non_heap.pool.* still should do the trick for you.

zt9788 · August 8, 2023, 6:45am

Hi, I set this
-Delastic.apm.disable_metrics=jvm.fd.*,jvm.memory.non_heap.pool.* but JVM metrics also not found in apm7.13.2 ,just only upgrade apm-server?

6fears7 · August 8, 2023, 12:10pm

I tested a higher version of the APM server and the problem went away.

system · September 5, 2023, 12:11pm

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