-
Bug
-
Resolution: Fixed
-
P2
-
17
-
b24
-
Not verified
Created on behalf of yude.lyd@alibaba-inc.com
-------------
Shenandoah hangs when running specjvm2008 derby using
java -Xmx24g -Xms24g -XX:ParallelGCThreads=16 -XX:+UseShenandoahGC -XX:-TieredCompilation -Xlog:gc*=debug,handshake=trace:file=510s.log:tid:filesize=200m -jar SPECjvm2008.jar -ict -coe -i 5 derby
The reason is that there is a reentrant handshake with the following stacktrace
"BenchmarkThread derby 45" #100 prio=5 os_prio=0 cpu=17601.80ms elapsed=29.87s tid=0x00007f0fa41adc10 nid=0x8c82 runnable [0x00007f0eb72f1000]
java.lang.Thread.State: RUNNABLE
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V [libjvm.so+0x7b07b4] HandshakeState::process_by_self()+0x54
V [libjvm.so+0xcbbd10] SafepointMechanism::process(JavaThread*)+0x60
V [libjvm.so+0xcbc04f] SafepointMechanism::process_if_requested_slow(JavaThread*)+0xf
V [libjvm.so+0x793af8] GenerateOopMap::do_interpretation(Thread*)+0x1a8
V [libjvm.so+0x793d56] GenerateOopMap::compute_map(Thread*)+0x256
V [libjvm.so+0xbf9794] OopMapForCacheEntry::compute_map(Thread*) [clone .part.0]+0x54
V [libjvm.so+0xbfaabb] OopMapCache::compute_one_oop_map(methodHandle const&, int, InterpreterOopMap*)+0x1bb
V [libjvm.so+0xb9a8de] Method::mask_for(int, InterpreterOopMap*)+0xae
V [libjvm.so+0x6bf73b] frame::oops_interpreted_do(OopClosure*, RegisterMap const*, bool) const+0x17b
V [libjvm.so+0xe84d5e] JavaThread::oops_do_frames(OopClosure*, CodeBlobClosure*) [clone .part.0]+0x6e
V [libjvm.so+0xd051c3] ShenandoahUpdateThreadClosure::do_thread(Thread*)+0x83
V [libjvm.so+0x7b03c3] HandshakeOperation::do_handshake(JavaThread*)+0x43
V [libjvm.so+0x7b05c6] HandshakeState::process_self_inner()+0x136
V [libjvm.so+0x7b07b4] HandshakeState::process_by_self()+0x54
V [libjvm.so+0xcbbd10] SafepointMechanism::process(JavaThread*)+0x60
V [libjvm.so+0xcbc04f] SafepointMechanism::process_if_requested_slow(JavaThread*)+0xf
V [libjvm.so+0xe8d655] JavaThread::check_special_condition_for_native_trans(JavaThread*)+0x95
j java.io.RandomAccessFile.writeBytes([BII)V+0 java.base@17-internal
J 1411 c2 java.io.RandomAccessFile.write([BII)V java.base@17-internal (8 bytes) @ 0x00007f1048739468 [0x00007f1048739420+0x0000000000000048]
j org.apache.derby.impl.store.raw.log.LogAccessFile.writeToLog([BII)V+25
j org.apache.derby.impl.store.raw.log.LogAccessFile.flushDirtyBuffers()V+92
j org.apache.derby.impl.store.raw.log.LogToFile.flush(JJ)V+220
J 1314 c2 org.apache.derby.impl.store.raw.log.LogToFile.flush(Lorg/apache/derby/iapi/store/raw/log/LogInstant;)V (39 bytes) @ 0x00007f104899c218 [0x00007f104899c1a0+0x0000000000000078]
J 1394 c2 org.apache.derby.impl.store.raw.xact.Xact.commit(I)Lorg/apache/derby/iapi/store/raw/log/LogInstant; (13 bytes) @ 0x00007f10489df7e8 [0x00007f10489df5a0+0x0000000000000248]
J 2822 c2 org.apache.derby.impl.store.access.RAMTransaction.commit()V (21 bytes) @ 0x00007f1048c668d4 [0x00007f1048c66840+0x0000000000000094]
j org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.doCommit(ZZIZ)V+307
J 2453 c2 spec.benchmarks.derby.DerbyHarness$Client.handleAccounts()V (471 bytes) @ 0x00007f1048b7da78 [0x00007f1048b7cc40+0x0000000000000e38]
j spec.benchmarks.derby.DerbyHarness$Client.run()V+1
j spec.benchmarks.derby.DerbyHarness.<init>(IIII)V+99
j spec.benchmarks.derby.DerbyHarness.main(IIII)V+10
j spec.benchmarks.derby.Main.runBenchmark(I)J+34
j spec.benchmarks.derby.Main.harnessMain()V+4
j spec.harness.BenchmarkThread.runLoop(Lspec/harness/results/IterationResult;)Lspec/harness/results/LoopResult;+74
j spec.harness.BenchmarkThread.executeIteration()Z+74
j spec.harness.BenchmarkThread.run()V+1
v ~StubRoutines::call_stub
V [libjvm.so+0x821375] JavaCalls::call_helper(JavaValue*, methodHandle const&, JavaCallArguments*, Thread*)+0x2a5
V [libjvm.so+0x822cf3] JavaCalls::call_virtual(JavaValue*, Handle, Klass*, Symbol*, Symbol*, Thread*)+0x1d3
V [libjvm.so+0x8e3c00] thread_entry(JavaThread*, Thread*)+0x70
V [libjvm.so+0xe877e0] JavaThread::thread_main_inner()+0xd0
V [libjvm.so+0xe8abae] Thread::call_run()+0xde
V [libjvm.so+0xc0cadf] thread_native_entry(Thread*)+0xdf
Aborted
This handshake blocks the Java Thread that tries to process it. And the VM Thread spins in VM_HandshakeAllThreads::doit(). From the outside, we can observe that the java process freezes and not responsive to Ctrl+C.
A simple fix is to check for reentrant handshake
https://github.com/linade/jdk/commit/45b533e72c5a1c108667ef3bb9675c72896cf5ec
I'm looking forward to some expert's opinion on this.
-----------
Edit:
Changed title as this is not Shenandoah-specific;
The above suggested fix is incorrect. A proper fix is to remove the safepoint poll introduced in 8262443.
-------------
Shenandoah hangs when running specjvm2008 derby using
java -Xmx24g -Xms24g -XX:ParallelGCThreads=16 -XX:+UseShenandoahGC -XX:-TieredCompilation -Xlog:gc*=debug,handshake=trace:file=510s.log:tid:filesize=200m -jar SPECjvm2008.jar -ict -coe -i 5 derby
The reason is that there is a reentrant handshake with the following stacktrace
"BenchmarkThread derby 45" #100 prio=5 os_prio=0 cpu=17601.80ms elapsed=29.87s tid=0x00007f0fa41adc10 nid=0x8c82 runnable [0x00007f0eb72f1000]
java.lang.Thread.State: RUNNABLE
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V [libjvm.so+0x7b07b4] HandshakeState::process_by_self()+0x54
V [libjvm.so+0xcbbd10] SafepointMechanism::process(JavaThread*)+0x60
V [libjvm.so+0xcbc04f] SafepointMechanism::process_if_requested_slow(JavaThread*)+0xf
V [libjvm.so+0x793af8] GenerateOopMap::do_interpretation(Thread*)+0x1a8
V [libjvm.so+0x793d56] GenerateOopMap::compute_map(Thread*)+0x256
V [libjvm.so+0xbf9794] OopMapForCacheEntry::compute_map(Thread*) [clone .part.0]+0x54
V [libjvm.so+0xbfaabb] OopMapCache::compute_one_oop_map(methodHandle const&, int, InterpreterOopMap*)+0x1bb
V [libjvm.so+0xb9a8de] Method::mask_for(int, InterpreterOopMap*)+0xae
V [libjvm.so+0x6bf73b] frame::oops_interpreted_do(OopClosure*, RegisterMap const*, bool) const+0x17b
V [libjvm.so+0xe84d5e] JavaThread::oops_do_frames(OopClosure*, CodeBlobClosure*) [clone .part.0]+0x6e
V [libjvm.so+0xd051c3] ShenandoahUpdateThreadClosure::do_thread(Thread*)+0x83
V [libjvm.so+0x7b03c3] HandshakeOperation::do_handshake(JavaThread*)+0x43
V [libjvm.so+0x7b05c6] HandshakeState::process_self_inner()+0x136
V [libjvm.so+0x7b07b4] HandshakeState::process_by_self()+0x54
V [libjvm.so+0xcbbd10] SafepointMechanism::process(JavaThread*)+0x60
V [libjvm.so+0xcbc04f] SafepointMechanism::process_if_requested_slow(JavaThread*)+0xf
V [libjvm.so+0xe8d655] JavaThread::check_special_condition_for_native_trans(JavaThread*)+0x95
j java.io.RandomAccessFile.writeBytes([BII)V+0 java.base@17-internal
J 1411 c2 java.io.RandomAccessFile.write([BII)V java.base@17-internal (8 bytes) @ 0x00007f1048739468 [0x00007f1048739420+0x0000000000000048]
j org.apache.derby.impl.store.raw.log.LogAccessFile.writeToLog([BII)V+25
j org.apache.derby.impl.store.raw.log.LogAccessFile.flushDirtyBuffers()V+92
j org.apache.derby.impl.store.raw.log.LogToFile.flush(JJ)V+220
J 1314 c2 org.apache.derby.impl.store.raw.log.LogToFile.flush(Lorg/apache/derby/iapi/store/raw/log/LogInstant;)V (39 bytes) @ 0x00007f104899c218 [0x00007f104899c1a0+0x0000000000000078]
J 1394 c2 org.apache.derby.impl.store.raw.xact.Xact.commit(I)Lorg/apache/derby/iapi/store/raw/log/LogInstant; (13 bytes) @ 0x00007f10489df7e8 [0x00007f10489df5a0+0x0000000000000248]
J 2822 c2 org.apache.derby.impl.store.access.RAMTransaction.commit()V (21 bytes) @ 0x00007f1048c668d4 [0x00007f1048c66840+0x0000000000000094]
j org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.doCommit(ZZIZ)V+307
J 2453 c2 spec.benchmarks.derby.DerbyHarness$Client.handleAccounts()V (471 bytes) @ 0x00007f1048b7da78 [0x00007f1048b7cc40+0x0000000000000e38]
j spec.benchmarks.derby.DerbyHarness$Client.run()V+1
j spec.benchmarks.derby.DerbyHarness.<init>(IIII)V+99
j spec.benchmarks.derby.DerbyHarness.main(IIII)V+10
j spec.benchmarks.derby.Main.runBenchmark(I)J+34
j spec.benchmarks.derby.Main.harnessMain()V+4
j spec.harness.BenchmarkThread.runLoop(Lspec/harness/results/IterationResult;)Lspec/harness/results/LoopResult;+74
j spec.harness.BenchmarkThread.executeIteration()Z+74
j spec.harness.BenchmarkThread.run()V+1
v ~StubRoutines::call_stub
V [libjvm.so+0x821375] JavaCalls::call_helper(JavaValue*, methodHandle const&, JavaCallArguments*, Thread*)+0x2a5
V [libjvm.so+0x822cf3] JavaCalls::call_virtual(JavaValue*, Handle, Klass*, Symbol*, Symbol*, Thread*)+0x1d3
V [libjvm.so+0x8e3c00] thread_entry(JavaThread*, Thread*)+0x70
V [libjvm.so+0xe877e0] JavaThread::thread_main_inner()+0xd0
V [libjvm.so+0xe8abae] Thread::call_run()+0xde
V [libjvm.so+0xc0cadf] thread_native_entry(Thread*)+0xdf
Aborted
This handshake blocks the Java Thread that tries to process it. And the VM Thread spins in VM_HandshakeAllThreads::doit(). From the outside, we can observe that the java process freezes and not responsive to Ctrl+C.
A simple fix is to check for reentrant handshake
https://github.com/linade/jdk/commit/45b533e72c5a1c108667ef3bb9675c72896cf5ec
I'm looking forward to some expert's opinion on this.
-----------
Edit:
Changed title as this is not Shenandoah-specific;
The above suggested fix is incorrect. A proper fix is to remove the safepoint poll introduced in 8262443.
- relates to
-
JDK-8262443 GenerateOopMap::do_interpretation can spin for a long time.
-
- Resolved
-