Rocreex Rocreex - 4 months ago 18
Java Question

Java ExecuterService deadlock?

Recently I wrote some code to read JSON data from the web and update a MongoDB entry according to the data recieved. This has to be done for about 500,000 entries. To accelerate the process, I use a

ThreadPoolExecutor
with 5 threads and a blocking queue of size 50. Furthermore I use the
CallerRunsPolicy
for handling excess jobs.
For every worker the job is as follows:


  1. Read JSON data from URL

  2. Parse JSON

  3. Update corresponding MongoDB entry



However the programm gets stuck every time. Sometimes early, sometimes only after some hours. So far I haven't found any faults in the code. Exceptions are handled but not thrown and all methods used are supposed to be thread safe.

Here is the thread dump after the programm hangs:

2016-01-16 23:40:05
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.66-b18 mixed mode):

"JMX server connection timeout 711" #711 daemon prio=5 os_prio=0 tid=0x000000001813d000 nid=0x4e8 in Object.wait() [0x000000004733f000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at com.sun.jmx.remote.internal.ServerCommunicatorAdmin$Timeout.run(Unknown Source)
- locked <0x00000000e26162c8> (a [I)
at java.lang.Thread.run(Unknown Source)

Locked ownable synchronizers:
- None

"RMI Scheduler(0)" #710 daemon prio=5 os_prio=0 tid=0x000000001813b800 nid=0x1ba0 waiting on condition [0x000000004723f000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000e1ce64e0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(Unknown Source)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(Unknown Source)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(Unknown Source)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.getTask(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)

Locked ownable synchronizers:
- None

"RMI TCP Connection(1)-192.168.56.1" #709 daemon prio=5 os_prio=0 tid=0x0000000017714000 nid=0x11f0 runnable [0x000000004713e000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(Unknown Source)
at java.net.SocketInputStream.read(Unknown Source)
at java.net.SocketInputStream.read(Unknown Source)
at java.io.BufferedInputStream.fill(Unknown Source)
at java.io.BufferedInputStream.read(Unknown Source)
- locked <0x00000000e25e5fe8> (a java.io.BufferedInputStream)
at java.io.FilterInputStream.read(Unknown Source)
at sun.rmi.transport.tcp.TCPTransport.handleMessages(Unknown Source)
at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(Unknown Source)
at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$256(Unknown Source)
at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler$$Lambda$1/917377658.run(Unknown Source)
at java.security.AccessController.doPrivileged(Native Method)
at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)

Locked ownable synchronizers:
- <0x00000000e23ce048> (a java.util.concurrent.ThreadPoolExecutor$Worker)

"RMI TCP Accept-0" #708 daemon prio=5 os_prio=0 tid=0x0000000017fa2000 nid=0xd18 runnable [0x0000000046f3e000]
java.lang.Thread.State: RUNNABLE
at java.net.DualStackPlainSocketImpl.accept0(Native Method)
at java.net.DualStackPlainSocketImpl.socketAccept(Unknown Source)
at java.net.AbstractPlainSocketImpl.accept(Unknown Source)
at java.net.PlainSocketImpl.accept(Unknown Source)
- locked <0x00000000e1ce8078> (a java.net.SocksSocketImpl)
at java.net.ServerSocket.implAccept(Unknown Source)
at java.net.ServerSocket.accept(Unknown Source)
at sun.management.jmxremote.LocalRMIServerSocketFactory$1.accept(Unknown Source)
at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(Unknown Source)
at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)

Locked ownable synchronizers:
- None

"pool-1-thread-5" #19 prio=5 os_prio=0 tid=0x000000001859e000 nid=0x628 waiting on condition [0x0000000018f9e000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000a57af940> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(Unknown Source)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(Unknown Source)
at java.util.concurrent.ArrayBlockingQueue.take(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.getTask(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)

Locked ownable synchronizers:
- None

"pool-1-thread-4" #18 prio=5 os_prio=0 tid=0x000000001859d800 nid=0x2208 waiting on condition [0x0000000018e9f000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000a57af940> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(Unknown Source)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(Unknown Source)
at java.util.concurrent.ArrayBlockingQueue.take(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.getTask(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)

Locked ownable synchronizers:
- None

"pool-1-thread-3" #17 prio=5 os_prio=0 tid=0x000000001859c800 nid=0x239c waiting on condition [0x0000000018d9e000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000a57af940> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(Unknown Source)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(Unknown Source)
at java.util.concurrent.ArrayBlockingQueue.take(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.getTask(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)

Locked ownable synchronizers:
- None

"pool-1-thread-2" #16 prio=5 os_prio=0 tid=0x000000001859a000 nid=0x18a8 runnable [0x0000000018c9e000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(Unknown Source)
at java.net.SocketInputStream.read(Unknown Source)
at java.net.SocketInputStream.read(Unknown Source)
at java.io.BufferedInputStream.fill(Unknown Source)
at java.io.BufferedInputStream.read1(Unknown Source)
at java.io.BufferedInputStream.read(Unknown Source)
- locked <0x00000000f921a080> (a java.io.BufferedInputStream)
at sun.net.www.http.HttpClient.parseHTTPHeader(Unknown Source)
at sun.net.www.http.HttpClient.parseHTTP(Unknown Source)
at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(Unknown Source)
- locked <0x00000000f921a0c0> (a sun.net.www.protocol.http.HttpURLConnection)
at sun.net.www.protocol.http.HttpURLConnection.getInputStream(Unknown Source)
- locked <0x00000000f921a0c0> (a sun.net.www.protocol.http.HttpURLConnection)
at java.net.URL.openStream(Unknown Source)
at Pr0grammDB.readURL(Pr0grammDB.java:217)
at Pr0grammDB.readJSON(Pr0grammDB.java:210)
at Pr0grammDB$1Job.run(Pr0grammDB.java:98)
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)

Locked ownable synchronizers:
- <0x00000000a57afa50> (a java.util.concurrent.ThreadPoolExecutor$Worker)

"pool-1-thread-1" #15 prio=5 os_prio=0 tid=0x0000000018599000 nid=0x20fc waiting on condition [0x0000000018b9f000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000a57af940> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(Unknown Source)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(Unknown Source)
at java.util.concurrent.ArrayBlockingQueue.take(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.getTask(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)

Locked ownable synchronizers:
- None

"pool-1-thread-1" #12 daemon prio=5 os_prio=0 tid=0x0000000017ecc800 nid=0x2bd8 waiting on condition [0x000000001879f000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000a57af298> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(Unknown Source)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(Unknown Source)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(Unknown Source)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.getTask(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)

Locked ownable synchronizers:
- None

"cluster-ClusterId{value='569a6466a802c513644d5a51', description='null'}-127.0.0.1:27017" #11 daemon prio=5 os_prio=0 tid=0x000000001785e000 nid=0x1de8 waiting on condition [0x000000001869e000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000a57ad528> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(Unknown Source)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(Unknown Source)
at com.mongodb.connection.DefaultServerMonitor$ServerMonitorRunnable.waitForSignalOrTimeout(DefaultServerMonitor.java:237)
at com.mongodb.connection.DefaultServerMonitor$ServerMonitorRunnable.waitForNext(DefaultServerMonitor.java:218)
at com.mongodb.connection.DefaultServerMonitor$ServerMonitorRunnable.run(DefaultServerMonitor.java:167)
- locked <0x00000000a57ad270> (a com.mongodb.connection.DefaultServerMonitor$ServerMonitorRunnable)
at java.lang.Thread.run(Unknown Source)

Locked ownable synchronizers:
- None

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

Locked ownable synchronizers:
- None

"C1 CompilerThread2" #8 daemon prio=9 os_prio=2 tid=0x0000000015af8800 nid=0x2f5c waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

Locked ownable synchronizers:
- None

"C2 CompilerThread1" #7 daemon prio=9 os_prio=2 tid=0x0000000015af1800 nid=0x18c0 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

Locked ownable synchronizers:
- None

"C2 CompilerThread0" #6 daemon prio=9 os_prio=2 tid=0x0000000015aef000 nid=0x15f8 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

Locked ownable synchronizers:
- None

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

Locked ownable synchronizers:
- None

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

Locked ownable synchronizers:
- None

"Finalizer" #3 daemon prio=8 os_prio=1 tid=0x00000000022b8000 nid=0x2f14 in Object.wait() [0x0000000016e4f000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000a57ebd08> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(Unknown Source)
- locked <0x00000000a57ebd08> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(Unknown Source)
at java.lang.ref.Finalizer$FinalizerThread.run(Unknown Source)

Locked ownable synchronizers:
- None

"Reference Handler" #2 daemon prio=10 os_prio=2 tid=0x00000000022af000 nid=0x83c in Object.wait() [0x0000000016d4f000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000a57ebf20> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Unknown Source)
at java.lang.ref.Reference$ReferenceHandler.run(Unknown Source)
- locked <0x00000000a57ebf20> (a java.lang.ref.Reference$Lock)

Locked ownable synchronizers:
- None

"main" #1 prio=5 os_prio=0 tid=0x000000000207e000 nid=0x1964 runnable [0x000000000217e000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(Unknown Source)
at java.net.SocketInputStream.read(Unknown Source)
at java.net.SocketInputStream.read(Unknown Source)
at java.io.BufferedInputStream.fill(Unknown Source)
at java.io.BufferedInputStream.read1(Unknown Source)
at java.io.BufferedInputStream.read(Unknown Source)
- locked <0x00000000f921c318> (a java.io.BufferedInputStream)
at sun.net.www.http.HttpClient.parseHTTPHeader(Unknown Source)
at sun.net.www.http.HttpClient.parseHTTP(Unknown Source)
at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(Unknown Source)
- locked <0x00000000f921c358> (a sun.net.www.protocol.http.HttpURLConnection)
at sun.net.www.protocol.http.HttpURLConnection.getInputStream(Unknown Source)
- locked <0x00000000f921c358> (a sun.net.www.protocol.http.HttpURLConnection)
at java.net.URL.openStream(Unknown Source)
at Pr0grammDB.readURL(Pr0grammDB.java:217)
at Pr0grammDB.readJSON(Pr0grammDB.java:210)
at Pr0grammDB$1Job.run(Pr0grammDB.java:98)
at java.util.concurrent.ThreadPoolExecutor$CallerRunsPolicy.rejectedExecution(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.reject(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.execute(Unknown Source)
at Pr0grammDB.addAdditionalData(Pr0grammDB.java:114)
at Pr0grammDB.main(Pr0grammDB.java:48)

Locked ownable synchronizers:
- None

"VM Thread" os_prio=2 tid=0x0000000015ab7000 nid=0x684 runnable

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00000000021d7800 nid=0x28e0 runnable

"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00000000021d9000 nid=0x2658 runnable

"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x00000000021da800 nid=0x273c runnable

"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x00000000021dd000 nid=0x20f8 runnable

"VM Periodic Task Thread" os_prio=2 tid=0x00000000174a2000 nid=0x824 waiting on condition

JNI global references: 385


All threads except for one seem to be waiting. However I don't know what they are waiting for. The other one seems to be stuck in socketRead.

When the code hangs the heap usage is somewhat weird, too. It ascends to about 400MB before dropping to 100MB and repeating. One cycle taking about 1h.

Maybe you can help me find the problem?

Answer

The solution was adding a timeout to the URLConnection, as obviously there is no standard timeout:

URL url = new URL(urlString);
URLConnection urlConn = url.openConnection();
urlConn.setConnectTimeout(10000);
urlConn.setReadTimeout(10000);
Comments