ExecutorService is causing the program to hang for few minutes

[Michael Henderson]

I wrote this simple program to learn how to use Poison Pill pattern to terminate threads. It runs to completion but after all the threads are done processing, the application hangs for few minutes before exiting code 0.

I've included the jstack output at the end. I had originally written this program to use Thread and Runnable and it worked perfect, ie, without hanging for few minutes before exiting. Any help or hint is appreciated.
thank you

import java.util.ArrayList;
import java.util.Collection;
import java.util.List;
import java.util.Random;
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;
import java.util.concurrent.LinkedBlockingQueue;

public class ProducersConsumers {
    private LinkedBlockingQueue<Item> queue = new LinkedBlockingQueue<Item>();
    private static final ExecutorService executorPool = Executors.newCachedThreadPool();
    private Random randGenerator = new Random(System.currentTimeMillis());

    private class Item {
        private boolean done = false;
        private String message;

        private Item(boolean done) {
            this.done = done;
        }

        private Item(String message) {
            this.message = message;
        }

        public boolean isDone() {
            return done;
        }

        public String getMessage() {
            return message;
        }
    }

    private class Producer implements Callable<Long> {
        private final int id;
        private Integer numOfMessages;

        private Producer(int id, int numOfMessages) {
            this.id = id;
            this.numOfMessages = numOfMessages;
        }

        @Override
        public Long call() throws Exception {
            long totalTime = 0;
            while (numOfMessages > 0) {
                String message;
                synchronized (numOfMessages) {
                    long starttime = System.nanoTime();
                    int msgLength = randGenerator.nextInt(20000);
                    StringBuilder sb = new StringBuilder(msgLength);
                    for (int a = 0; a < msgLength; a++) {
                        sb.append((char) ('a' + randGenerator.nextInt(26)));
                    }
                    message = sb.toString();
                    long endtime = System.nanoTime();
                    totalTime += endtime - starttime;
                }
                numOfMessages--;
                queue.put(new Item(message));
            }
            System.out.println("-------------Producer " + id + " is done.");
            queue.put(new Item(true));
            return totalTime;
        }
    }

    private class Consumer implements Callable<Long> {
        private String monitor = "monitor";
        private final int id;

        private Consumer(int id) {
            this.id = id;
        }

        @Override
        public Long call() throws Exception {
            long totalTime = 0;
            while (true) {
                Item item = queue.take();
                if (item.isDone()) {
                    break;
                }
                synchronized (monitor) {
                    long starttime = System.nanoTime();
                    StringBuilder sb = new StringBuilder(item.getMessage());
                    sb = sb.reverse();
                    String message = sb.toString();
                    long endtime = System.nanoTime();
                    totalTime += endtime - starttime;
                }
            }
            System.out.println("+++++++++++++Consumer " + id + " is done.");
            return totalTime;
        }
    }

    public void begin(int threadCount) throws InterruptedException, ExecutionException {
        Collection<Producer> producers = new ArrayList<Producer>();
        for (int i = 0; i < threadCount; i++) {
            producers.add(new Producer(i, randGenerator.nextInt(5)));
        }
        Collection<Consumer> consumers = new ArrayList<Consumer>();
        for (int i = 0; i < threadCount; i++) {
            consumers.add(new Consumer(i));
        }
        try {
            long starttime = System.nanoTime();
            List<Future<Long>> producerFutureList = executorPool.invokeAll(producers);
            List<Future<Long>> consumerFutureList = executorPool.invokeAll(consumers);
            long producerTotalTime = 0;
            long consumerTotalTime = 0;

            for (Future<Long> future : producerFutureList) {
                producerTotalTime += future.get();
            }
            for (Future<Long> future : consumerFutureList) {
                consumerTotalTime += future.get();
            }
            long mainThreadTotalTime = System.nanoTime() - starttime;

            System.out.println("producerTotalTime   " + producerTotalTime);
            System.out.println("consumerTotalTime   " + consumerTotalTime);
            System.out.println("mainThreadTotalTime " + mainThreadTotalTime);
            System.out.println("Difference          " + (producerTotalTime + consumerTotalTime - mainThreadTotalTime));
        } catch (InterruptedException e) {
            e.printStackTrace();  //To change body of catch statement use File | Settings | File Templates.
            throw e;
        } catch (ExecutionException e) {
            e.printStackTrace();  //To change body of catch statement use File | Settings | File Templates.
            throw e;
        }

    }

    public static void main(String[] args) throws ExecutionException, InterruptedException {
        ProducersConsumers prodcon = new ProducersConsumers();
        prodcon.begin(20);
    }
}

jstack output is

2011-07-20 12:01:20
Full thread dump Java HotSpot(TM) 64-Bit Server VM (20.1-b02-384 mixed mode):

"Attach Listener" daemon prio=9 tid=104000800 nid=0x10dca8000 waiting on condition [00000000]
   java.lang.Thread.State: RUNNABLE

"DestroyJavaVM" prio=5 tid=1018a1000 nid=0x100501000 waiting on condition [00000000]
   java.lang.Thread.State: RUNNABLE

"pool-1-thread-12" prio=5 tid=10b08e000 nid=0x10db22000 waiting on condition [10db21000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <7f3113510> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:424)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:323)
	at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:874)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:945)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
	at java.lang.Thread.run(Thread.java:680)

"pool-1-thread-11" prio=5 tid=102878800 nid=0x10da1f000 waiting on condition [10da1e000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <7f3113510> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:424)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:323)
	at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:874)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:945)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
	at java.lang.Thread.run(Thread.java:680)

"pool-1-thread-10" prio=5 tid=10b08d000 nid=0x10d91c000 waiting on condition [10d91b000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <7f3113510> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:424)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:323)
	at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:874)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:945)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
	at java.lang.Thread.run(Thread.java:680)

"pool-1-thread-9" prio=5 tid=102878000 nid=0x10d819000 waiting on condition [10d818000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <7f3113510> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:424)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:323)
	at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:874)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:945)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
	at java.lang.Thread.run(Thread.java:680)

"pool-1-thread-8" prio=5 tid=10189f800 nid=0x10d716000 waiting on condition [10d715000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <7f3113510> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:424)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:323)
	at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:874)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:945)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
	at java.lang.Thread.run(Thread.java:680)

"pool-1-thread-7" prio=5 tid=10189f000 nid=0x10d613000 waiting on condition [10d612000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <7f3113510> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:424)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:323)
	at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:874)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:945)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
	at java.lang.Thread.run(Thread.java:680)

"pool-1-thread-6" prio=5 tid=10419b000 nid=0x10d510000 waiting on condition [10d50f000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <7f3113510> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:424)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:323)
	at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:874)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:945)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
	at java.lang.Thread.run(Thread.java:680)

"pool-1-thread-5" prio=5 tid=10419a800 nid=0x10d40d000 waiting on condition [10d40c000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <7f3113510> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:424)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:323)
	at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:874)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:945)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
	at java.lang.Thread.run(Thread.java:680)

"pool-1-thread-4" prio=5 tid=104199800 nid=0x10d30a000 waiting on condition [10d309000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <7f3113510> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:424)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:323)
	at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:874)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:945)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
	at java.lang.Thread.run(Thread.java:680)

"pool-1-thread-3" prio=5 tid=10b0f6000 nid=0x10d207000 waiting on condition [10d206000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <7f3113510> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:424)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:323)
	at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:874)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:945)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
	at java.lang.Thread.run(Thread.java:680)

"pool-1-thread-2" prio=5 tid=102877000 nid=0x10d104000 waiting on condition [10d103000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <7f3113510> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:424)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:323)
	at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:874)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:945)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
	at java.lang.Thread.run(Thread.java:680)

"pool-1-thread-1" prio=5 tid=10284e000 nid=0x10d001000 waiting on condition [10d000000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <7f3113510> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:424)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:323)
	at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:874)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:945)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
	at java.lang.Thread.run(Thread.java:680)

"Low Memory Detector" daemon prio=5 tid=10b03c800 nid=0x10cc0d000 runnable [00000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" daemon prio=9 tid=10180a000 nid=0x10cb0a000 waiting on condition [00000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" daemon prio=9 tid=101809800 nid=0x10ca07000 waiting on condition [00000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=9 tid=10b03b800 nid=0x10c904000 runnable [00000000]
   java.lang.Thread.State: RUNNABLE

"Surrogate Locker Thread (Concurrent GC)" daemon prio=5 tid=101808800 nid=0x10c801000 waiting on condition [00000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=8 tid=104096800 nid=0x10c307000 in Object.wait() [10c306000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <7f3001300> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
	- locked <7f3001300> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=104096000 nid=0x10c204000 in Object.wait() [10c203000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <7f30011d8> (a java.lang.ref.Reference$Lock)
	at java.lang.Object.wait(Object.java:485)
	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
	- locked <7f30011d8> (a java.lang.ref.Reference$Lock)

"VM Thread" prio=9 tid=104091000 nid=0x10c101000 runnable 

"Gang worker#0 (Parallel GC Threads)" prio=9 tid=104002000 nid=0x102501000 runnable 

"Gang worker#1 (Parallel GC Threads)" prio=9 tid=104002800 nid=0x102604000 runnable 

"Gang worker#2 (Parallel GC Threads)" prio=9 tid=104003000 nid=0x102707000 runnable 

"Gang worker#3 (Parallel GC Threads)" prio=9 tid=104004000 nid=0x107902000 runnable 

"Concurrent Mark-Sweep GC Thread" prio=9 tid=10407f000 nid=0x10acf3000 runnable 
"VM Periodic Task Thread" prio=10 tid=102812000 nid=0x10cd10000 waiting on condition 

"Exception Catcher Thread" prio=10 tid=104001800 nid=0x1017f9000 runnable 
JNI global references: 910