Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-8225036

FutureTask object doesn't Lock itself for Future get() that is waiting for lock

XMLWordPrintable

      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)

            vklang Viktor Klang
            webbuggrp Webbug Group
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Created:
              Updated: