Logo Questions Linux Laravel Mysql Ubuntu Git Menu
 

Why does ScheduledExecutorService.shutdown() uses 100% of my CPU?

I've got the following simple code:

package main;

import java.util.concurrent.*;

public class Main {

    public static void main(String[] args) throws InterruptedException {
        new Main();
    }

    public Main() throws InterruptedException {
        ScheduledExecutorService executor = Executors.newScheduledThreadPool(1);
        executor.schedule(new MyRunnable(), 10, TimeUnit.SECONDS);
        System.out.println("Shutting down...");
        executor.shutdown();
        System.out.println("Awaiting termination...");
        executor.awaitTermination(Long.MAX_VALUE, TimeUnit.MINUTES);
        System.out.println("Main finished!");
    }

    private class MyRunnable implements Runnable {
        public void run() {
            System.out.println("Finished running!");
        }
    }

}

Actually, although my real code is a bit more complex than that, I could isolate the issue in those lines. The code basically waits for 10 seconds to run the runnable and then notifies the ending of the main program.

However, I noticed for a 10 second period, one of my core is used at 100%.

If I comment this line:

executor.awaitTermination(Long.MAX_VALUE, TimeUnit.MINUTES);

The cpu core is also used at 100% and also the main program finishes before the Runnable.

If I comment this line:

executor.shutdown();

The cpu is properly used but the program won't finish.

If I comment both of the previous lines, the cpu is properly used but the main program won't finish.

  1. Is there something wrong with my code?
  2. Is executor.shutdown(); doing some kind of busy waiting instead of just disabling submission of new tasks?
  3. Or should I blame the JVM?

Additonal details:

$ java -version
java version "1.6.0_26"
Java(TM) SE Runtime Environment (build 1.6.0_26-b03)
Java HotSpot(TM) Server VM (build 20.1-b02, mixed mode)

$ uname -a
Linux XPSG 2.6.32-5-686-bigmem #1 SMP Sun May 6 04:39:05 UTC 2012 i686 GNU/Linux

PS: Please, don't ask me to use a CountDownLatch nor newSingleThreadScheduledExecutor. That is not related to the question I'm asking. Thanks.

Edit:

Here is the java dump:

Full thread dump Java HotSpot(TM) Server VM (20.1-b02 mixed mode):

"pool-1-thread-1" prio=10 tid=0x08780c00 nid=0x32ee runnable [0x6fdcc000]
   java.lang.Thread.State: RUNNABLE
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:943)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
    at java.lang.Thread.run(Thread.java:662)

"Low Memory Detector" daemon prio=10 tid=0x0874dc00 nid=0x32ec runnable [0x00000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" daemon prio=10 tid=0x0874c000 nid=0x32eb waiting on condition [0x00000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" daemon prio=10 tid=0x0874a000 nid=0x32ea waiting on condition [0x00000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x08748800 nid=0x32e9 waiting on condition [0x00000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=10 tid=0x0873a000 nid=0x32e8 in Object.wait() [0x70360000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x9e8f1150> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
    - locked <0x9e8f1150> (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=0x08735400 nid=0x32e7 in Object.wait() [0x703b1000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x9e8f1050> (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 <0x9e8f1050> (a java.lang.ref.Reference$Lock)

"main" prio=10 tid=0x086b5c00 nid=0x32e3 waiting on condition [0xb6927000]
   java.lang.Thread.State: TIMED_WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x9e958998> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2025)
    at java.util.concurrent.ThreadPoolExecutor.awaitTermination(ThreadPoolExecutor.java:1253)
    at main.Main.<init>(Main.java:19)
    at main.Main.main(Main.java:10)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at org.eclipse.jdt.internal.jarinjarloader.JarRsrcLoader.main(JarRsrcLoader.java:58)

"VM Thread" prio=10 tid=0x08731800 nid=0x32e6 runnable 

"GC task thread#0 (ParallelGC)" prio=10 tid=0x086bd000 nid=0x32e4 runnable 

"GC task thread#1 (ParallelGC)" prio=10 tid=0x086be400 nid=0x32e5 runnable 

"VM Periodic Task Thread" prio=10 tid=0x0874fc00 nid=0x32ed waiting on condition 

JNI global references: 931

Heap
 PSYoungGen      total 18752K, used 645K [0x9e8f0000, 0x9fdd0000, 0xb3790000)
  eden space 16128K, 4% used [0x9e8f0000,0x9e991510,0x9f8b0000)
  from space 2624K, 0% used [0x9fb40000,0x9fb40000,0x9fdd0000)
  to   space 2624K, 0% used [0x9f8b0000,0x9f8b0000,0x9fb40000)
 PSOldGen        total 42880K, used 0K [0x74b90000, 0x77570000, 0x9e8f0000)
  object space 42880K, 0% used [0x74b90000,0x74b90000,0x77570000)
 PSPermGen       total 16384K, used 2216K [0x70b90000, 0x71b90000, 0x74b90000)
  object space 16384K, 13% used [0x70b90000,0x70dba198,0x71b90000)
like image 706
Mosty Mostacho Avatar asked May 19 '12 23:05

Mosty Mostacho


2 Answers

It is in fact busy waiting. There seems to be no backoff logic for the ThreadPoolExecutor to wait until all tasks are completed (note that this only occurs when you shutdown() otherwise it will suspend the thread correctly).

It is continuously checking to see if a task is ready to be executed if it isnt it will try again until the elapsed time has passed for the task to be scheduled.

There is a trade off for shutting down a scheduled thread pool (this trade off is imposed by the implementation). It is to busy spin until the task is ready to schedule or shutdownNow where no queue'd tasks would be executed. However you can then take the list of Runnable's returned and execute them yourself.

like image 122
John Vint Avatar answered Nov 07 '22 00:11

John Vint


This is a platform specific problem. When I ran your test program on my machine, the CPU usage was approximately zero in the 10 second shutdown period ... according to my machine's CPU usage monitoring.

$ java -version
java version "1.7.0_03"
Java(TM) SE Runtime Environment (build 1.7.0_03-b04)
Java HotSpot(TM) Client VM (build 22.1-b02, mixed mode, sharing)

I did a cursory search of the Java bugs database, and nothing relevant showed up.

Looking at the different versions of the source code that you can find on the net (Google), it is clear that the getTask method and friends have had a lot of work done on them between (early) Java 1.6 and (current) Java 1.7.

I suggest that you try upgrading your JVM to either the latest Java 1.6 or to Java 1.7. Or at least try this out for your test program. (Or just live with it. This is hardly a show stopper ...)


FYI, this page includes instructions on how to install various versions of Java on Ubuntu.

  • One option (for Java 7) is to use the "duinsoft" installer which is a script that pulls the installer from the Oracle site. They've even set up a deb repository to host the installer.

  • Another option is to install the openjdk-7-jdk or openjdk-7-jre packages which are in the 11.10 repos.

And while you are in the area, don't forget to vote on this RFE to provide the debian package/installer for Java 7.

For the record, this mess is largely a result of Oracle withdrawing licensing for OEM redistibution which mean that the "sun-java-6" package had to be withdrawn. And of course, the "minor problem" that Oracle doesn't provide DEBs.

like image 3
Stephen C Avatar answered Nov 07 '22 00:11

Stephen C