-
Enhancement
-
Resolution: Unresolved
-
P4
-
None
-
8, 11, 12, 13
-
x86_64
-
os_x
A DESCRIPTION OF THE PROBLEM :
I've been curious about a problem that I face on a JVM process that I wanted to detect if there is any performance issue.
The jstack dump with -l option should shows all locks acquiring and waiting for all threads, which means if a thread is waiting on a specific lock, that lock should be appeared in the jstack dump in another thread owns that lock, something like;
1- The waiting thread
"t1" #254 daemon prio=5 os_prio=0 tid=0x00007ed72c052000 nid=0x34da waiting on condition [0x00007ed45b6f4000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00007ee311518a40> (a java.util.concurrent.FutureTask)
2- The blocking thread/owner of the lock
"t2" #250 daemon prio=5 os_prio=0 tid=0x00007ed72c04b000 nid=0x34d6 runnable [0x00007ed4bc192000]
java.lang.Thread.State: RUNNABLE
...
- locked <0x00007ee311518a40> (a java.util.concurrent.FutureTask)
...
- The above wasn't the case on my jstack dump, a lot of threads was waiting like the first case, thread t1, but there is no any locked statement belongs to any thread like the second thread t2.
I did some experiments and it seems that when calling future.get it ends up calling LockSupport.park(this); in FutureTask object, but the running FutureTask that decorates Runnable and Callable which are submitted by Executor doesn't owns/locks explicitly any kind of lock, this issue will result a lot of confusion about detecting performance issues especially if the JVM has lot of Executor submit and Future get methods call.
A suggestion would be to lock that thread in FutureTask constructor or run method, that will have no bad effect on other submits for that same Runnable/Callable since FutureTask Object is created for each submit call regardless if the same Runnable/Callable object is submitted again or not.
STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
Run the following code
import java.util.ArrayList;
import java.util.Date;
import java.util.List;
import java.util.concurrent.Callable;
import java.util.concurrent.ExecutionException;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.Future;
public class MyCallable implements Callable<String> {
@Override
public String call() throws Exception {
Thread.sleep(100000);
//return the thread name executing this callable task
return Thread.currentThread().getName();
}
public static void main(String args[]) {
ExecutorService executor = Executors.newFixedThreadPool(1);
Callable<String> callable = new MyCallable();
Future future = executor.submit(callable);
try {
System.out.println(new Date() + "::" + future.get());
} catch (InterruptedException | ExecutionException e) {
e.printStackTrace();
}
}
}
Take Jstack dump by issuing : jstack -l ${PROC_ID}
EXPECTED VERSUS ACTUAL BEHAVIOR :
EXPECTED -
"main" #1 prio=5 os_prio=31 tid=0x00007fed32801000 nid=0x1603 waiting on condition [0x0000700004e62000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x000000076ac3ff18> (a java.util.concurrent.FutureTask)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:429)
at java.util.concurrent.FutureTask.get(FutureTask.java:191)
at MyCallable.main(MyCallable.java:30)
"pool-1-thread-1" #11 prio=5 os_prio=31 tid=0x00007fed32843000 nid=0xa803 waiting on condition [0x000070000629e000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at MyCallable.call(MyCallable.java:15)
at MyCallable.call(MyCallable.java:11)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
with any kind of mention that this thread locked 0x000000076ac3ff18
ACTUAL -
"main" #1 prio=5 os_prio=31 tid=0x00007fed32801000 nid=0x1603 waiting on condition [0x0000700004e62000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x000000076ac3ff18> (a java.util.concurrent.FutureTask)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:429)
at java.util.concurrent.FutureTask.get(FutureTask.java:191)
at MyCallable.main(MyCallable.java:30)
"pool-1-thread-1" #11 prio=5 os_prio=31 tid=0x00007fed32843000 nid=0xa803 waiting on condition [0x000070000629e000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at MyCallable.call(MyCallable.java:15)
at MyCallable.call(MyCallable.java:11)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
I've been curious about a problem that I face on a JVM process that I wanted to detect if there is any performance issue.
The jstack dump with -l option should shows all locks acquiring and waiting for all threads, which means if a thread is waiting on a specific lock, that lock should be appeared in the jstack dump in another thread owns that lock, something like;
1- The waiting thread
"t1" #254 daemon prio=5 os_prio=0 tid=0x00007ed72c052000 nid=0x34da waiting on condition [0x00007ed45b6f4000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00007ee311518a40> (a java.util.concurrent.FutureTask)
2- The blocking thread/owner of the lock
"t2" #250 daemon prio=5 os_prio=0 tid=0x00007ed72c04b000 nid=0x34d6 runnable [0x00007ed4bc192000]
java.lang.Thread.State: RUNNABLE
...
- locked <0x00007ee311518a40> (a java.util.concurrent.FutureTask)
...
- The above wasn't the case on my jstack dump, a lot of threads was waiting like the first case, thread t1, but there is no any locked statement belongs to any thread like the second thread t2.
I did some experiments and it seems that when calling future.get it ends up calling LockSupport.park(this); in FutureTask object, but the running FutureTask that decorates Runnable and Callable which are submitted by Executor doesn't owns/locks explicitly any kind of lock, this issue will result a lot of confusion about detecting performance issues especially if the JVM has lot of Executor submit and Future get methods call.
A suggestion would be to lock that thread in FutureTask constructor or run method, that will have no bad effect on other submits for that same Runnable/Callable since FutureTask Object is created for each submit call regardless if the same Runnable/Callable object is submitted again or not.
STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
Run the following code
import java.util.ArrayList;
import java.util.Date;
import java.util.List;
import java.util.concurrent.Callable;
import java.util.concurrent.ExecutionException;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.Future;
public class MyCallable implements Callable<String> {
@Override
public String call() throws Exception {
Thread.sleep(100000);
//return the thread name executing this callable task
return Thread.currentThread().getName();
}
public static void main(String args[]) {
ExecutorService executor = Executors.newFixedThreadPool(1);
Callable<String> callable = new MyCallable();
Future future = executor.submit(callable);
try {
System.out.println(new Date() + "::" + future.get());
} catch (InterruptedException | ExecutionException e) {
e.printStackTrace();
}
}
}
Take Jstack dump by issuing : jstack -l ${PROC_ID}
EXPECTED VERSUS ACTUAL BEHAVIOR :
EXPECTED -
"main" #1 prio=5 os_prio=31 tid=0x00007fed32801000 nid=0x1603 waiting on condition [0x0000700004e62000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x000000076ac3ff18> (a java.util.concurrent.FutureTask)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:429)
at java.util.concurrent.FutureTask.get(FutureTask.java:191)
at MyCallable.main(MyCallable.java:30)
"pool-1-thread-1" #11 prio=5 os_prio=31 tid=0x00007fed32843000 nid=0xa803 waiting on condition [0x000070000629e000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at MyCallable.call(MyCallable.java:15)
at MyCallable.call(MyCallable.java:11)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
with any kind of mention that this thread locked 0x000000076ac3ff18
ACTUAL -
"main" #1 prio=5 os_prio=31 tid=0x00007fed32801000 nid=0x1603 waiting on condition [0x0000700004e62000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x000000076ac3ff18> (a java.util.concurrent.FutureTask)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:429)
at java.util.concurrent.FutureTask.get(FutureTask.java:191)
at MyCallable.main(MyCallable.java:30)
"pool-1-thread-1" #11 prio=5 os_prio=31 tid=0x00007fed32843000 nid=0xa803 waiting on condition [0x000070000629e000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at MyCallable.call(MyCallable.java:15)
at MyCallable.call(MyCallable.java:11)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)