Java hangs for a minute after a program is finished

Question

We have a Java command line utility program used during build process of a large application. Since recently (apparently after upgrading Java to OpenJDK Runtime Environment (build 1.8.0_212-b04) — the program is not used that often, so I haven't noticed when exactly this started to happen) it hangs for about a minute after main() has finished. I.e. it hangs somewhere in Java internals, not in our code, though our code might indirectly cause this somehow.

The program uses Javassist (3.25) to instrument some Java classes that are previously compiled with javac. Unfortunately, I cannot post the program itself because it is quite large and complex and also proprietary.

After about a minute of hanging the program exits normally — process return code is zero, nothing is printed to either stderr or stdout. Produced results are also as expected.

Below is thread stack dump extracted with jstack utility from thus "hung" process. As you can see, there are no threads executing anything from our program anymore, all threads are in Java internals at this point.

Has anyone encountered something similar or have any ideas what's going on?

2019-05-22 12:51:34
Full thread dump OpenJDK 64-Bit Server VM (25.212-b04 mixed mode):

"Attach Listener" #12 daemon prio=9 os_prio=0 tid=0x00007f196c001000 nid=0x3c3a waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"DestroyJavaVM" #11 prio=5 os_prio=0 tid=0x00007f19c0059800 nid=0x3b6c waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"pool-1-thread-1" #10 prio=5 os_prio=0 tid=0x00007f19c0d1b800 nid=0x3b8e waiting on condition [0x00007f1985f21000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x0000000776280730> (a java.util.concurrent.SynchronousQueue$TransferStack)
        at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
        at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:460)
        at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:362)
        at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:941)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1073)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)

"Service Thread" #9 daemon prio=9 os_prio=0 tid=0x00007f19c0145800 nid=0x3b87 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread3" #8 daemon prio=9 os_prio=0 tid=0x00007f19c013a000 nid=0x3b86 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread2" #7 daemon prio=9 os_prio=0 tid=0x00007f19c0138000 nid=0x3b85 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x00007f19c0136000 nid=0x3b84 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0x00007f19c0133000 nid=0x3b83 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x00007f19c0126800 nid=0x3b82 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007f19c00fa800 nid=0x3b81 in Object.wait() [0x00007f198727c000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x0000000776289088> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
        - locked <0x0000000776289088> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216)

"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007f19c00f5800 nid=0x3b80 in Object.wait() [0x00007f198737d000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x0000000776280990> (a java.lang.ref.Reference$Lock)
        at java.lang.Object.wait(Object.java:502)
        at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
        - locked <0x0000000776280990> (a java.lang.ref.Reference$Lock)
        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

"VM Thread" os_prio=0 tid=0x00007f19c00ec000 nid=0x3b7f runnable 

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007f19c006c000 nid=0x3b6d runnable 

"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007f19c006e000 nid=0x3b76 runnable 

"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x00007f19c0070000 nid=0x3b77 runnable 

"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x00007f19c0071800 nid=0x3b78 runnable 

"GC task thread#4 (ParallelGC)" os_prio=0 tid=0x00007f19c0073800 nid=0x3b79 runnable 

"GC task thread#5 (ParallelGC)" os_prio=0 tid=0x00007f19c0075800 nid=0x3b7a runnable 

"GC task thread#6 (ParallelGC)" os_prio=0 tid=0x00007f19c0077000 nid=0x3b7d runnable 

"GC task thread#7 (ParallelGC)" os_prio=0 tid=0x00007f19c0079000 nid=0x3b7e runnable 

"VM Periodic Task Thread" os_prio=0 tid=0x00007f19c0148000 nid=0x3b88 waiting on condition 

JNI global references: 313

Can you run it in a debugger and "break" when it is hung. Based on stack trace there is something still running and refusing to exit. Do you have any thread that wakes up every minute or so? If not check the threads with the debugger and see what it is waiting on (examine the Object.wait() threads specifically and tryHandlePending may imply it's part of a try block trying to cleanup). — AlexC, May 22 '19 at 12:50

score 3 · Accepted Answer · answered May 22 '19 at 15:55

3

OK, turned out it is not bug and has nothing to do with the Java upgrade. It is because Executors.newCachedThreadPool() uses non-daemon threads, which cause the application to stay alive a minute after the last task is finished. (The pool had always been there, but a recent change in our application submitted a task to it, so it became non-empty.)

So I need to either call shutdown() on it or use answers to this question to create a daemon-thread pool.

answered May 22 '19 at 15:55

2

The clue in the thread dump is the `"pool-1-thread-1"` thread, which lacks a `daemon` flag and is therefore keeping the program alive. – John Kugelman May 22 '19 at 16:00
Good spot, as per docs _"Threads that have not been used for sixty seconds are terminated and removed from the cache."_ – Karol Dowbecki May 22 '19 at 16:01

Java hangs for a minute after a program is finished

1 Answers1