Java VM keeps running CARepeater after closing Phoebus

[pavel-ch]

Environment: Windows 10 x64, Orace Java:
java version "10.0.2" 2018-07-17
Java(TM) SE Runtime Environment 18.3 (build 10.0.2+13)
Java HotSpot(TM) 64-Bit Server VM 18.3 (build 10.0.2+13, mixed mode)

After a correct closing of the main window and shutdown of Phoebus, sometimes (not always, but in a high percentage) the Java VM keeps running. Libs and/or product JAR files are locked by this running instance, making next Maven compile cycle impossible (errors in the cleaning step Cannot delete xxx.jar). The Java instance has to be manually stopped from Task manager.
This behavior is observed for a longer time, also on another (Windows 7 x64 Java 9) setup. The issue thus seems being independent from OS and Java version, at least on Windows, and from my personal setup.
It seems that something in Phoebus does not shut correctly down. It may depend on what applications have been started inside Phoebus, although no closer investigation in this regard has been done.
As I am not any Java specialist, I can not debug this because I do not know how to.

[kasemir]

The reason is usually that some plain threads keep running which should be daemon threads, i.e. threads that don't prevent the JVM from exiting.
I just fixed one such issue by using a daemon thread pool in the ProposalService,
53ffcbb

If you find that phoebus doesn't quit, run jps to list process IDs and identify the phoebus process. Or look for the initial log message 2018-12-13 08:26:08 INFO [org.phoebus.product.Launcher] Phoebus (PID 442) that shows the process ID.
Then run jstack 442 with that process ID to get the stack trace and find threads that are still running.

Again daemon threads are OK:

"JobViewer" #26 daemon prio=5 os_prio=0 tid=0x00007f29844f8000 nid=0x221 waiting on condition  [0x00007f298a4bf000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at jdk.internal.misc.Unsafe.park(java.base@10.0.2/Native Method)
        - parking to wait for  <0x00000006d2fbd038> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos(java.base@10.0.2/LockSupport.java:234)
...
"ProposalService" #35 daemon prio=5 os_prio=0 tid=0x00007f2984754800 nid=0x1681 waiting on condition  [0x00007f298a660000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at jdk.internal.misc.Unsafe.park(java.base@10.0.2/Native Method)
        - parking to wait for  <0x00000006d2f26420> (a java.util.concurrent.SynchronousQueue$TransferStack)
...

but we would be interested in non-daemon threads and their stack trace:

"JavaFX Application Thread" #19 prio=5 os_prio=0 tid=0x00007f299c136000 nid=0x1e7 runnable  [0x00007f2990955000]
   java.lang.Thread.State: RUNNABLE
        at com.sun.glass.ui.gtk.GtkApplication._runLoop(javafx.graphics@10.0.2/Native Method)
        at com.sun.glass.ui.gtk.GtkApplication.lambda$runLoop$11(javafx.graphics@10.0.2/GtkApplication.java:277)
        at com.sun.glass.ui.gtk.GtkApplication$$Lambda$84/210567393.run(javafx.graphics@10.0.2/Unknown Source)
        at java.lang.Thread.run(java.base@10.0.2/Thread.java:844)

[pavel-ch]

CARepeater?

C:>jps
54532 Jps
47512 CARepeater

C:>jstack 47512
2018-12-14 17:08:22
Full thread dump Java HotSpot(TM) 64-Bit Server VM (10.0.2+13 mixed mode):

Threads class SMR info:
_java_thread_list=0x0000020affd1a820, length=11, elements={
0x0000020afc701800, 0x0000020affa13000, 0x0000020affa1c800, 0x0000020affa78800,
0x0000020affa79800, 0x0000020affa30800, 0x0000020affa7d800, 0x0000020affa8d800,
0x0000020affaf1000, 0x0000020aa41b4800, 0x0000020aa41ba000
}

"main" #1 prio=5 os_prio=0 tid=0x0000020afc701800 nid=0x8560 runnable [0x000000fe17dff000]
java.lang.Thread.State: RUNNABLE
at java.net.TwoStacksPlainDatagramSocketImpl.receive0(java.base@10.0.2/Native Method)
- locked <0x00000006d1ab05b8> (a java.net.TwoStacksPlainDatagramSocketImpl)
at java.net.TwoStacksPlainDatagramSocketImpl.receive(java.base@10.0.2/TwoStacksPlainDatagramSocketImpl.java:114)
- locked <0x00000006d1ab05b8> (a java.net.TwoStacksPlainDatagramSocketImpl)
at java.net.DatagramSocket.receive(java.base@10.0.2/DatagramSocket.java:814)
- locked <0x00000006d1aad4d8> (a java.net.DatagramPacket)
- locked <0x00000006d1aad718> (a java.net.DatagramSocket)
at com.cosylab.epics.caj.CARepeater.process(CARepeater.java:479)
at com.cosylab.epics.caj.CARepeater.run(CARepeater.java:265)
at com.cosylab.epics.caj.CARepeater.main(CARepeater.java:683)

"Reference Handler" #2 daemon prio=10 os_prio=2 tid=0x0000020affa13000 nid=0x1c78 waiting on condition [0x000000fe18aff000]
java.lang.Thread.State: RUNNABLE
at java.lang.ref.Reference.waitForReferencePendingList(java.base@10.0.2/Native Method)
at java.lang.ref.Reference.processPendingReferences(java.base@10.0.2/Reference.java:174)
at java.lang.ref.Reference.access$000(java.base@10.0.2/Reference.java:44)
at java.lang.ref.Reference$ReferenceHandler.run(java.base@10.0.2/Reference.java:138)

"Finalizer" #3 daemon prio=8 os_prio=1 tid=0x0000020affa1c800 nid=0xcc64 in Object.wait() [0x000000fe18bfe000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(java.base@10.0.2/Native Method)
- waiting on <0x00000006d2309410> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(java.base@10.0.2/ReferenceQueue.java:151)
- waiting to re-lock in wait() <0x00000006d2309410> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(java.base@10.0.2/ReferenceQueue.java:172)
at java.lang.ref.Finalizer$FinalizerThread.run(java.base@10.0.2/Finalizer.java:216)

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

"Attach Listener" #5 daemon prio=5 os_prio=2 tid=0x0000020affa79800 nid=0x12ddc waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #6 daemon prio=9 os_prio=2 tid=0x0000020affa30800 nid=0x10914 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
No compile task

"C2 CompilerThread1" #7 daemon prio=9 os_prio=2 tid=0x0000020affa7d800 nid=0xe1d8 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
No compile task

"C1 CompilerThread2" #8 daemon prio=9 os_prio=2 tid=0x0000020affa8d800 nid=0x818c waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
No compile task

"Sweeper thread" #9 daemon prio=9 os_prio=2 tid=0x0000020affaf1000 nid=0x120d8 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

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

"Common-Cleaner" #11 daemon prio=8 os_prio=1 tid=0x0000020aa41ba000 nid=0x2ca0 in Object.wait() [0x000000fe193ff000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(java.base@10.0.2/Native Method)
- waiting on <0x00000006d229ca10> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(java.base@10.0.2/ReferenceQueue.java:151)
- waiting to re-lock in wait() <0x00000006d229ca10> (a java.lang.ref.ReferenceQueue$Lock)
at jdk.internal.ref.CleanerImpl.run(java.base@10.0.2/CleanerImpl.java:148)
at java.lang.Thread.run(java.base@10.0.2/Thread.java:844)
at jdk.internal.misc.InnocuousThread.run(java.base@10.0.2/InnocuousThread.java:134)

"VM Thread" os_prio=2 tid=0x0000020affa0d000 nid=0x14d50 runnable

"GC Thread#0" os_prio=2 tid=0x0000020afc71b800 nid=0xb83c runnable

"GC Thread#1" os_prio=2 tid=0x0000020afc71e000 nid=0x3840 runnable

"GC Thread#2" os_prio=2 tid=0x0000020afc71f800 nid=0xbbac runnable

"GC Thread#3" os_prio=2 tid=0x0000020afc722800 nid=0x10fbc runnable

"G1 Main Marker" os_prio=2 tid=0x0000020afc776800 nid=0x14198 runnable

"G1 Conc#0" os_prio=2 tid=0x0000020afc779800 nid=0xded0 runnable

"G1 Refine#0" os_prio=2 tid=0x0000020afeb53800 nid=0xc620 runnable

"G1 Refine#1" os_prio=2 tid=0x0000020afeb54800 nid=0x2a98 runnable

"G1 Refine#2" os_prio=2 tid=0x0000020afeb55000 nid=0x160 runnable

"G1 Refine#3" os_prio=2 tid=0x0000020afeb57000 nid=0x7c08 runnable

"G1 Young RemSet Sampling" os_prio=2 tid=0x0000020afeb5a000 nid=0x9174 runnable
"VM Periodic Task Thread" os_prio=2 tid=0x0000020aa41ba800 nid=0x7df8 waiting on condition

JNI global references: 10

[kasemir]

That's different.
The CA client library might start the CA Repeater as a separate process.
So when phoebus starts for the first time and connects to PVs, it also starts the CA Repeater process.

==> You should see two processes, the CA Repeater and phoebus.

When you then quit phoebus, phoebus quits but the CA Repeater keeps running.

==> You should see the CA Repeater, no more phoebus.

Start a new phoebus instance

==> You should see two processes, the (old) CA Repeater and (new ) phoebus.

When you then quit phoebus, phoebus quits but the CA Repeater keeps running.

==> You should see the CA Repeater, no more phoebus.

So phoebus quits OK in these examples.
The CA Repeater is meant to stay running.

I see how that causes the problem with keeping the JCA.jar locked, but I'm afraid this is how it's supposed to work.

So you'll have to kill that CA Repeater process.

[kasemir]

On Linux, it looks like this in the process list:

... /opt/openjdk-11+28/bin/java -classpath ./product-sns-0.0.1.jar com.cosylab.epics.caj.CARepeater -p 5065

The point is that this is not the original JVM that ran phoebus which has a dangling thread and thus cannot close. It's a separate process, running another copy of the JVM for the CARepeater, and that process is meant to run forever.

On startup, the CA client library checks if a CA repeater is running. If not, it starts one.

[kasemir]

Based on looking at the source code, https://github.com/epics-base/jca/blob/master/src/core/com/cosylab/epics/caj/CARepeater.java, try setting the JVM property CA_DISABLE_REPEATER:

  -DCA_DISABLE_REPEATER=true

when you start phoebus. That might disable the CA Repeater, and avoid the trouble that you have.

[kasemir]

Yup, that does it for me.
I killed the running CA Repeater, then added -DCA_DISABLE_REPEATER=true to the script that starts phoebus:

java -jar product-0.0.1.jar -DCA_DISABLE_REPEATER=true 

--> No more CA Repeater.

[pavel-ch]

Ok thank you I give it a try and some more investigation.

[pavel-ch]

The point is that this is not the original JVM that ran phoebus

Seems that on Windows, the JVM running CARepeater keeps all the Phoebus jar opened after Phoebus exit.
Confirmed with ProcessExplorer.
So on Windows, the JVM running CARepeater probably IS the same JVM which ran Phoebus.

[pavel-ch]

The
-DCA_DISABLE_REPEATER=true
trick works for me, however, better to find some reason for a different behaviour on a platform.

[kasemir]

Seems that on Windows, the JVM running CARepeater keeps all the Phoebus jar opened

Of course, same as on Linux, because it's using the same product-0.0.1.jar etc.
It's another copy of the JVM, using the same jar files as phoebus, so it's locking them.

[pavel-ch]

I see. In another words, this is a "normal behaviour" and the only way to suppress it is to disable repeater.
Closing the issue.