ArrayIndexOutOfBoundsException when elastic.apm.profiling_inferred_spans_enabled is set to true

[quachc]

Describe the bug

elastic-apm-sampling-profiler stops with java.lang.ArrayIndexOutOfBoundsException

Steps to reproduce

I'm using a Spring Boot web application with a Postgres database, packages as a standalone jar.
Command to run:

java -javaagent:[/path/to/agent]/elastic-apm-agent-1.16.0.jar \
 -Delastic.apm.service_name=my-service \
 -Delastic.apm.application_packages=my.package \
 -Delastic.apm.profiling_inferred_spans_enabled=true \
 -jar my-service-0.0.1.jar

Expected behavior

Spans based on the profiler data as described here: https://www.elastic.co/blog/from-distributed-tracing-to-distributed-profiling-with-elastic-apm

Debug logs

uname -a
Linux my-host 5.4.0-37-generic #41-Ubuntu SMP Wed Jun 3 18:57:02 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux

java --version
openjdk 11.0.7 2020-04-14
OpenJDK Runtime Environment AdoptOpenJDK (build 11.0.7+10)
OpenJDK 64-Bit Server VM AdoptOpenJDK (build 11.0.7+10, mixed mode

Click to expand

2020-06-11 15:45:27.021 [elastic-apm-server-healthcheck] INFO co.elastic.apm.agent.report.ApmServerHealthChecker - Elastic APM server is available: {  "build_date": "2020-05-28T14:42:11Z",  "build_sha": "0102a80acd2c83e4ab9cce93dc630b877e3063e7",  "version": "7.7.1"}
2020-06-11 15:45:27.047 [main] INFO co.elastic.apm.agent.util.JmxUtils - Found JVM-specific OperatingSystemMXBean interface: com.sun.management.OperatingSystemMXBean
2020-06-11 15:45:27.107 [main] INFO co.elastic.apm.agent.configuration.StartupInfo - Starting Elastic APM 1.16.0 as veiling-service on Java 11.0.7 (AdoptOpenJDK) Linux 5.4.0-37-generic
2020-06-11 15:45:27.109 [elastic-apm-remote-config-poller] INFO co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Received new configuration from APM Server: {}
2020-06-11 15:45:27.123 [main] INFO co.elastic.apm.agent.impl.ElasticApmTracer - Tracer switched to RUNNING state
.....
2020-06-11 15:45:33.926 [main] INFO co.elastic.apm.agent.servlet.ServletVersionInstrumentation - Servlet container info = Apache Tomcat/9.0.35
.....
2020-06-11 15:45:58.078 [elastic-apm-sampling-profiler] ERROR co.elastic.apm.agent.profiler.SamplingProfiler - Stopping profiler
java.lang.ArrayIndexOutOfBoundsException: Index -1 out of bounds for length 16
	at co.elastic.apm.agent.collections.LongList.get(LongList.java:75)
	at co.elastic.apm.agent.collections.LongList.remove(LongList.java:98)
	at co.elastic.apm.agent.profiler.CallTree.stealLastChildId(CallTree.java:536)
	at co.elastic.apm.agent.profiler.CallTree.end(CallTree.java:285)
	at co.elastic.apm.agent.profiler.CallTree.end(CallTree.java:294)
	at co.elastic.apm.agent.profiler.CallTree.end(CallTree.java:294)
	at co.elastic.apm.agent.profiler.CallTree.end(CallTree.java:294)
	at co.elastic.apm.agent.profiler.CallTree.end(CallTree.java:294)
	at co.elastic.apm.agent.profiler.CallTree.end(CallTree.java:294)
	at co.elastic.apm.agent.profiler.CallTree.end(CallTree.java:294)
	at co.elastic.apm.agent.profiler.CallTree.end(CallTree.java:294)
	at co.elastic.apm.agent.profiler.CallTree.end(CallTree.java:294)
	at co.elastic.apm.agent.profiler.CallTree.end(CallTree.java:306)
	at co.elastic.apm.agent.profiler.CallTree.end(CallTree.java:306)
	at co.elastic.apm.agent.profiler.CallTree.end(CallTree.java:306)
	at co.elastic.apm.agent.profiler.CallTree.end(CallTree.java:306)
	at co.elastic.apm.agent.profiler.CallTree.end(CallTree.java:306)
	at co.elastic.apm.agent.profiler.CallTree.end(CallTree.java:306)
	at co.elastic.apm.agent.profiler.CallTree.end(CallTree.java:306)
	at co.elastic.apm.agent.profiler.CallTree.end(CallTree.java:306)
	at co.elastic.apm.agent.profiler.CallTree.end(CallTree.java:306)
	at co.elastic.apm.agent.profiler.CallTree.end(CallTree.java:306)
	at co.elastic.apm.agent.profiler.CallTree.end(CallTree.java:306)
	at co.elastic.apm.agent.profiler.CallTree.end(CallTree.java:306)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:212)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202)
	at co.elastic.apm.agent.profiler.CallTree$Root.addStackTrace(CallTree.java:663)
	at co.elastic.apm.agent.profiler.SamplingProfiler.processTraces(SamplingProfiler.java:448)
	at co.elastic.apm.agent.profiler.SamplingProfiler.profile(SamplingProfiler.java:351)
	at co.elastic.apm.agent.profiler.SamplingProfiler.run(SamplingProfiler.java:317)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:834)

[felixbarny]

Closing as duplicate of #1227

[quachc]

@felixbarny sorry, I did search the issues but I missed that one..
I'll try the snapshot

[felixbarny]

No worries at all, let me know how it goes 🙂

[quachc]

@felixbarny
Lots of:

2020-06-11 16:04:45,806 [elastic-apm-sampling-profiler] WARN  co.elastic.apm.agent.profiler.SamplingProfiler - Removing call tree for thread 454 because of exception while adding a stack trace: class java.lang.ArrayIndexOutOfBoundsException arraycopy: last destination index 70 out of bounds for long[64]

But sampling works and I can see the spans in Kibana APM

[felixbarny]

Could you enable debug logging and share the corresponding stack trace?

[quachc]

lol.. that was a lot of debug logging, I think this is one of them..

2020-06-11 18:59:51,033 [elastic-apm-sampling-profiler] WARN  co.elastic.apm.agent.profiler.SamplingProfiler - Removing call tree for thread 441 because of exception while adding a stack trace: class java.lang.ArrayIndexOutOfBoundsException arraycopy: last destination index 34 out of bounds for long[32]
2020-06-11 18:59:51,033 [elastic-apm-sampling-profiler] DEBUG co.elastic.apm.agent.profiler.SamplingProfiler - arraycopy: last destination index 34 out of bounds for long[32]
java.lang.ArrayIndexOutOfBoundsException: arraycopy: last destination index 34 out of bounds for long[32]
	at java.lang.System.arraycopy(Native Method) ~[?:?]
	at co.elastic.apm.agent.collections.LongList.addAll(LongList.java:57) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.transferMaybeChildIdsToChildIds(CallTree.java:230) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:214) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree.addFrame(CallTree.java:202) ~[?:?]
	at co.elastic.apm.agent.profiler.CallTree$Root.addStackTrace(CallTree.java:663) ~[?:?]
	at co.elastic.apm.agent.profiler.SamplingProfiler.processTraces(SamplingProfiler.java:449) [?:?]
	at co.elastic.apm.agent.profiler.SamplingProfiler.profile(SamplingProfiler.java:351) [?:?]
	at co.elastic.apm.agent.profiler.SamplingProfiler.run(SamplingProfiler.java:317) [?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
	at java.lang.Thread.run(Thread.java:834) [?:?]