Async-profiler: SIGSEGV on wall clock mode

[krzysztofslusarski]

$ cat hs_err_pid4096.log 
#
# A fatal error has been detected by the Java Runtime Environment:
#
#  SIGSEGV (0xb) at pc=0x00007fc6694c9fdb, pid=4096, tid=5215
#
# JRE version: OpenJDK Runtime Environment (11.0.6+10) (build 11.0.6+10-LTS)
# Java VM: OpenJDK 64-Bit Server VM (11.0.6+10-LTS, mixed mode, tiered, compressed oops, g1 gc, linux-amd64)
# Problematic frame:
# C  [libasyncProfiler.so+0xffdb]  Engine::getNativeTrace(void*, int, void const**, int, CodeCache*, CodeCache*)+0xab
#
# No core dump will be written. Core dumps have been disabled. To enable core dumping, try "ulimit -c unlimited" before starting Java again
#
# If you would like to submit a bug report, please visit:
#   http://bugreport.java.com/bugreport/crash.jsp
#

Current thread (0x00007fc63c0e4800):  JavaThread "hystrix-***-1" daemon [_thread_in_vm, id=5215, stack(0x00007fc61f1d5000,0x00007fc61f2d6000)]

Stack: [0x00007fc61f1d5000,0x00007fc61f2d6000],  sp=0x00007fc61f2d2350,  free space=1012k
Native frames: (J=compiled Java code, A=aot compiled Java code, j=interpreted, Vv=VM code, C=native code)
C  [libasyncProfiler.so+0xffdb]  Engine::getNativeTrace(void*, int, void const**, int, CodeCache*, CodeCache*)+0xab
C  [libasyncProfiler.so+0x1066f]  Profiler::getNativeTrace(void*, ASGCT_CallFrame*, int)+0x4f
C  [libasyncProfiler.so+0x110d7]  Profiler::recordSample(void*, unsigned long long, int, _jmethodID*, ThreadState)+0xc7
C  [libpthread.so.0+0xf5f0]
C  [libc.so.6+0x78099]  vsnprintf+0x79

Java frames: (J=compiled Java code, j=interpreted, Vv=VM code)
v  ~RuntimeStub::_new_array_nozero_Java
J 61060 c2 com.sun.xml.messaging.saaj.util.ByteOutputStream.write(Ljava/io/InputStream;)V (96 bytes) @ 0x00007fc716a2f078 [0x00007fc716a2e580+0x0000000000000af8]
J 125476 c2 com.sun.xml.messaging.saaj.soap.SOAPPartImpl.setContent(Ljavax/xml/transform/Source;)V (187 bytes) @ 0x00007fc7138d4b50 [0x00007fc7138d4940+0x0000000000000210]
J 125477 c2 com.sun.xml.messaging.saaj.soap.MessageImpl.init(Ljavax/xml/soap/MimeHeaders;ILcom/sun/xml/messaging/saaj/packaging/mime/internet/ContentType;Ljava/io/InputStream;)V (818 bytes) @ 0x00007fc7138fb614 [0x00007fc7138fb380+0x0000000000000294]
J 75665 c2 org.springframework.ws.transport.AbstractWebServiceConnection.receive(Lorg/springframework/ws/WebServiceMessageFactory;)Lorg/springframework/ws/WebServiceMessage; (43 bytes) @ 0x00007fc71926bf38 [0x00007fc71926bac0+0x0000000000000478]
J 88496 c2 org.springframework.ws.client.core.WebServiceTemplate.doSendAndReceive(Lorg/springframework/ws/context/MessageContext;Lorg/springframework/ws/transport/WebServiceConnection;Lorg/springframework/ws/client/core/WebServiceMessageCallback;Lorg/springframework/ws/client/core/WebServiceMessageExtractor;)Ljava/lang/Object; (314 bytes) @ 0x00007fc71af168b0 [0x00007fc71af165e0+0x00000000000002d0]
J 90819 c2 org.springframework.ws.client.core.WebServiceTemplate.marshalSendAndReceive(Ljava/lang/Object;)Ljava/lang/Object; (7 bytes) @ 0x00007fc71b613370 [0x00007fc71b612a60+0x0000000000000910]
J 90833 c2 ***(Lorg/aopalliance/intercept/MethodInvocation;)L***; (329 bytes) @ 0x00007fc71b6197ac [0x00007fc71b619540+0x000000000000026c]
J 57176 c2 ***.WebServiceProxy$$Lambda$1219.invoke(Lorg/aopalliance/intercept/MethodInvocation;)Ljava/lang/Object; (9 bytes) @ 0x00007fc716a70000 [0x00007fc716a6ffc0+0x0000000000000040]
J 36720 c2 org.springframework.aop.framework.JdkDynamicAopProxy.invoke(Ljava/lang/Object;Ljava/lang/reflect/Method;[Ljava/lang/Object;)Ljava/lang/Object; (575 bytes) @ 0x00007fc7142e6b30 [0x00007fc7142e5da0+0x0000000000000d90]
J 106045 c2 ***(Ljava/lang/String;Ljava/lang/String;Ljava/lang/String;Ljava/lang/String;Ljava/lang/String;Ljava/lang/String;)Ljava/util/List; (157 bytes) @ 0x00007fc71ef6bcf0 [0x00007fc71ef6a960+0x0000000000001390]
J 163925 c1 jdk.internal.reflect.GeneratedMethodAccessor8222.invoke(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object; (105 bytes) @ 0x00007fc70d28c1d4 [0x00007fc70d28b900+0x00000000000008d4]
J 91314 c2 com.netflix.hystrix.contrib.javanica.command.MethodExecutionAction.executeWithArgs(Lcom/netflix/hystrix/contrib/javanica/command/ExecutionType;[Ljava/lang/Object;)Ljava/lang/Object; (58 bytes) @ 0x00007fc71b768a9c [0x00007fc71b7687a0+0x00000000000002fc]
J 91315 c2 com.netflix.hystrix.contrib.javanica.command.AbstractHystrixCommand.process(Lcom/netflix/hystrix/contrib/javanica/command/AbstractHystrixCommand$Action;)Ljava/lang/Object; (83 bytes) @ 0x00007fc71b76bbdc [0x00007fc71b76bb60+0x000000000000007c]
J 82109 c2 com.netflix.hystrix.HystrixCommand$2.call()Ljava/lang/Object; (5 bytes) @ 0x00007fc719e7f59c [0x00007fc719e7f4a0+0x00000000000000fc]
J 63016 c2 rx.internal.operators.OnSubscribeDefer.call(Ljava/lang/Object;)V (9 bytes) @ 0x00007fc717580a34 [0x00007fc7175809c0+0x0000000000000074]
J 38862 c2 rx.internal.operators.OnSubscribeLift.call(Ljava/lang/Object;)V (9 bytes) @ 0x00007fc714691ee8 [0x00007fc714691d80+0x0000000000000168]
J 38862 c2 rx.internal.operators.OnSubscribeLift.call(Ljava/lang/Object;)V (9 bytes) @ 0x00007fc714691ee8 [0x00007fc714691d80+0x0000000000000168]
J 38862 c2 rx.internal.operators.OnSubscribeLift.call(Ljava/lang/Object;)V (9 bytes) @ 0x00007fc714691ee8 [0x00007fc714691d80+0x0000000000000168]
J 63016 c2 rx.internal.operators.OnSubscribeDefer.call(Ljava/lang/Object;)V (9 bytes) @ 0x00007fc717580c88 [0x00007fc7175809c0+0x00000000000002c8]
J 58354 c2 rx.internal.operators.OnSubscribeDoOnEach.call(Ljava/lang/Object;)V (9 bytes) @ 0x00007fc716c35cb4 [0x00007fc716c35920+0x0000000000000394]
J 38862 c2 rx.internal.operators.OnSubscribeLift.call(Ljava/lang/Object;)V (9 bytes) @ 0x00007fc714691ee8 [0x00007fc714691d80+0x0000000000000168]
J 83309 c2 com.netflix.hystrix.strategy.concurrency.HystrixContexSchedulerAction$1.call()Ljava/lang/Void; (41 bytes) @ 0x00007fc713aa8cb4 [0x00007fc713aa8860+0x0000000000000454]
J 157177 c2 rx.internal.schedulers.ScheduledAction.run()V (75 bytes) @ 0x00007fc71be91604 [0x00007fc71be90a80+0x0000000000000b84]
J 31677 c2 java.util.concurrent.Executors$RunnableAdapter.call()Ljava/lang/Object; [email protected] (14 bytes) @ 0x00007fc71371ef6c [0x00007fc71371ef20+0x000000000000004c]
J 60968 c2 java.util.concurrent.FutureTask.run()V [email protected] (123 bytes) @ 0x00007fc7153b03dc [0x00007fc7153b02e0+0x00000000000000fc]
J 53642% c2 java.util.concurrent.ThreadPoolExecutor.runWorker(Ljava/util/concurrent/ThreadPoolExecutor$Worker;)V [email protected] (187 bytes) @ 0x00007fc715d05f94 [0x00007fc715d05d60+0x0000000000000234]
j  java.util.concurrent.ThreadPoolExecutor$Worker.run()V+5 [email protected]
j  java.lang.Thread.run()V+11 [email protected]
v  ~StubRoutines::call_stub

siginfo: si_signo: 11 (SIGSEGV), si_code: 2 (SEGV_ACCERR), si_addr: 0x00007fc61f2d636f

Register to memory mapping:

RAX=0x0000000000000003 is an unknown value
RBX=0x00007fc7326dac55: <offset 0x0000000000a7cc55> in /opt/jdk_11.0.6.10.1_corretto/lib/server/libjvm.so at 0x00007fc731c5e000
RCX=0x00007fc61f2d23d0 is pointing into the stack for thread: 0x00007fc63c0e4800
RDX=0x00007fc61f2d6367 is pointing into the stack for thread: 0x00007fc63c0e2800
RSP=0x00007fc61f2d2350 is pointing into the stack for thread: 0x00007fc63c0e4800
RBP=0x00007fc61f2d23a0 is pointing into the stack for thread: 0x00007fc63c0e4800
RSI=0x00007fc61f313740 is pointing into the stack for thread: 0x00007fc63c0e2800
RDI=0x00007fc61f2d6367 is pointing into the stack for thread: 0x00007fc63c0e2800
R8 =0x0000000000000080 is an unknown value
R9 =0x00007fc669afa190: _ZN8Profiler9_instanceE+0x0000000000408230 in /opt/profiler/async-profiler-custom/build/libasyncProfiler.so at 0x00007fc6694ba000
R10=0x0 is NULL
R11=0x0000000000000246 is an unknown value
R12=0x00007fc669afa190: _ZN8Profiler9_instanceE+0x0000000000408230 in /opt/profiler/async-profiler-custom/build/libasyncProfiler.so at 0x00007fc6694ba000
R13=0x00007fc669afa1b0: _ZN8Profiler9_instanceE+0x0000000000408250 in /opt/profiler/async-profiler-custom/build/libasyncProfiler.so at 0x00007fc6694ba000
R14=0x0000000000000080 is an unknown value
R15=0x00007fc61f2d2360 is pointing into the stack for thread: 0x00007fc63c0e4800


Registers:
RAX=0x0000000000000003, RBX=0x00007fc7326dac55, RCX=0x00007fc61f2d23d0, RDX=0x00007fc61f2d6367
RSP=0x00007fc61f2d2350, RBP=0x00007fc61f2d23a0, RSI=0x00007fc61f313740, RDI=0x00007fc61f2d6367
R8 =0x0000000000000080, R9 =0x00007fc669afa190, R10=0x0000000000000000, R11=0x0000000000000246
R12=0x00007fc669afa190, R13=0x00007fc669afa1b0, R14=0x0000000000000080, R15=0x00007fc61f2d2360
RIP=0x00007fc6694c9fdb, EFLAGS=0x0000000000010212, CSGSFS=0x6f2e000000000033, ERR=0x0000000000000004
  TRAPNO=0x000000000000000e

Top of Stack: (sp=0x00007fc61f2d2350)
0x00007fc61f2d2350:   2d494b223d644920 00007fc61f2d23c0
0x00007fc61f2d2360:   00007fc61f2d2880 00007fc61f2d3400
0x00007fc61f2d2370:   3831633662633636 00007fc61f2d23c0
0x00007fc61f2d2380:   00007fc660de5610 00007fc6696f1f60 

Instructions: (pc=0x00007fc6694c9fdb)
0x00007fc6694c9edb:   e8 c0 df ff ff 48 8b 05 c1 6e 22 00 48 8b 00 c9
0x00007fc6694c9eeb:   c3 0f 1f 40 00 55 48 8d 05 74 b6 01 00 48 89 e5
0x00007fc6694c9efb:   5d c3 0f 1f 00 55 48 8d 05 d5 c4 01 00 48 89 e5
0x00007fc6694c9f0b:   5d c3 0f 1f 00 48 8b 05 91 6e 22 00 55 48 89 e5
0x00007fc6694c9f1b:   48 8b 00 5d c3 55 b8 02 00 00 00 48 89 e5 5d c3
0x00007fc6694c9f2b:   90 0f 1f 40 00 55 48 89 e5 41 57 41 56 41 55 41
0x00007fc6694c9f3b:   54 53 48 83 ec 28 48 85 f6 4c 8b 6d 10 0f 84 b2
0x00007fc6694c9f4b:   00 00 00 4c 8d 7d c0 48 89 75 c0 45 89 c6 4d 89
0x00007fc6694c9f5b:   cc 48 89 4d b8 4c 89 ff e8 28 e0 ff ff 4c 89 ff
0x00007fc6694c9f6b:   48 8b 18 e8 4d e4 ff ff 48 8b 10 48 8d 75 c8 48
0x00007fc6694c9f7b:   81 fb ff 0f 00 00 48 89 55 c8 76 79 45 85 f6 7e
0x00007fc6694c9f8b:   74 48 8b 4d b8 31 c0 66 0f 1f 44 00 00 49 39 5c
0x00007fc6694c9f9b:   24 10 77 19 49 39 5c 24 18 76 12 48 83 c4 28 5b
0x00007fc6694c9fab:   41 5c 41 5d 41 5e 41 5f 5d c3 0f 1f 00 49 39 5d
0x00007fc6694c9fbb:   10 77 06 49 3b 5d 18 72 e2 83 c0 01 48 39 d6 48
0x00007fc6694c9fcb:   89 19 73 d7 48 81 c6 00 00 04 00 48 39 d6 76 cb
0x00007fc6694c9fdb:   48 8b 5a 08 48 83 c1 08 48 8b 3a 48 81 fb ff 0f
0x00007fc6694c9feb:   00 00 76 b7 41 39 c6 7e b2 48 89 d6 48 89 fa eb
0x00007fc6694c9ffb:   9c 0f 1f 40 00 48 83 c4 28 31 c0 5b 41 5c 41 5d
0x00007fc6694ca00b:   41 5e 41 5f 5d c3 66 2e 0f 1f 84 00 00 00 00 00
0x00007fc6694ca01b:   0f 1f 44 00 00 55 48 63 ce 48 bf 95 e9 d1 5b 93
0x00007fc6694ca02b:   a7 a4 c6 48 0f af cf 85 f6 48 89 e5 7e 3d 8d 46
0x00007fc6694ca03b:   ff 48 89 fe 48 c1 e0 04 4c 8d 44 02 10 0f 1f 84
0x00007fc6694ca04b:   00 00 00 00 00 48 89 f7 48 83 c2 10 48 0f af 7a
0x00007fc6694ca05b:   f8 48 89 f8 48 c1 e8 2f 48 31 f8 48 0f af c6 48
0x00007fc6694ca06b:   31 c1 48 0f af ce 4c 39 c2 75 da 48 89 ca 48 b8
0x00007fc6694ca07b:   95 e9 d1 5b 93 a7 a4 c6 48 c1 ea 2f 48 31 ca 48
0x00007fc6694ca08b:   0f af d0 5d 48 89 d0 48 c1 e8 2f 48 31 d0 c3 66
0x00007fc6694ca09b:   0f 1f 44 00 00 55 48 89 e5 44 8b 8f 20 82 40 00
0x00007fc6694ca0ab:   45 8d 04 31 44 3b 87 10 82 40 00 7f 55 44 89 c8
0x00007fc6694ca0bb:   f0 44 0f b1 87 20 82 40 00 75 de 85 f6 44 89 49
0x00007fc6694ca0cb:   10 89 71 14 7e 3a 49 63 c1 44 8d 46 ff 31 c9 48 


Stack slot to memory mapping:
stack at sp + 0 slots: 0x2d494b223d644920 is an unknown value
stack at sp + 1 slots: 0x00007fc61f2d23c0 is pointing into the stack for thread: 0x00007fc63c0e4800
stack at sp + 2 slots: 0x00007fc61f2d2880 is pointing into the stack for thread: 0x00007fc63c0e4800
stack at sp + 3 slots: 0x00007fc61f2d3400 is pointing into the stack for thread: 0x00007fc63c0e4800
stack at sp + 4 slots: 0x3831633662633636 is an unknown value
stack at sp + 5 slots: 0x00007fc61f2d23c0 is pointing into the stack for thread: 0x00007fc63c0e4800
stack at sp + 6 slots: 0x00007fc660de5610 points into unknown readable memory: f6 ff ff ff c6 7f 00 00
stack at sp + 7 slots: 0x00007fc6696f1f60: _ZN8Profiler9_instanceE+0x0000000000000000 in /opt/profiler/async-profiler-custom/build/libasyncProfiler.so at 0x00007fc6694ba000

```

[krzysztofslusarski]

Additional info - profiler Was NOT attached as agent. It SIGSEGV after 8225 succesful runs (start/stop every minute).

[apangin]

Thank you for the report.
It seems like the native part of the stack was not in a walkable state, presumably, in the middle of calling a VM function from a runtime stub, but the profiler tried to walk it as a normal stack.

I added checks to avoid this kind of false positives.

[krzysztofslusarski]

We are going to test it on test env. till friday, if it is ok, we will deploy it on production.

[krzysztofslusarski]

I'm closing issue. After 150000 runs it didn't hang.

[SylvainJuge]

@apangin could that be worth doing a new minor release with this fix ? While we haven't noticed any instance of this error in the field with https://github.com/elastic/apm-agent-java/ any change that makes it safer is welcome.

[apangin]

@SylvainJuge Yes, that was my plan. There is one more issue I want to fix before the release: #363. Once I'm done with it, I'll publish a new version (I think, early next week).