Opened 6 years ago

Closed 5 years ago

#1286 closed defect (fixed)

java deadlock

Reported by: user Owned by: zzz
Priority: blocker Milestone: 0.9.13
Component: router/transport Version: 0.9.12
Keywords: deadlock, yellow tunnels, no traffic, no fast peers, no high capacity peers, no connectivity, expired leasesets Cc:
Parent Tickets: Sensitive: no

Description

on -21-rc:

with bote, sam, bob, i2psnark, running, I got this resulting in a state of total inconnectivity (0kbps):

2014/05/18 17:38:09 | "Wrapper-Control-Event-Monitor" daemon prio=6 tid=0x041bf000 nid=0x31f4 waiting on condition [0x03bcf000]
2014/05/18 17:38:09 |    java.lang.Thread.State: TIMED_WAITING (sleeping)
2014/05/18 17:38:09 | 	at java.lang.Thread.sleep(Native Method)
2014/05/18 17:38:09 | 	at org.tanukisoftware.wrapper.WrapperManager$3.run(WrapperManager.java:1034)
2014/05/18 17:38:09 | 
2014/05/18 17:38:09 | "Service Thread" daemon prio=6 tid=0x018b5000 nid=0x324c runnable [0x00000000]
2014/05/18 17:38:09 |    java.lang.Thread.State: RUNNABLE
2014/05/18 17:38:09 | 
2014/05/18 17:38:09 | "C1 CompilerThread0" daemon prio=10 tid=0x018a7000 nid=0x30bc waiting on condition [0x00000000]
2014/05/18 17:38:09 |    java.lang.Thread.State: RUNNABLE
2014/05/18 17:38:09 | 
2014/05/18 17:38:09 | "Attach Listener" daemon prio=10 tid=0x018a6000 nid=0x3240 runnable [0x00000000]
2014/05/18 17:38:09 |    java.lang.Thread.State: RUNNABLE
2014/05/18 17:38:09 | 
2014/05/18 17:38:09 | "Signal Dispatcher" daemon prio=10 tid=0x018a2c00 nid=0x312c waiting on condition [0x00000000]
2014/05/18 17:38:09 |    java.lang.Thread.State: RUNNABLE
2014/05/18 17:38:09 | 
2014/05/18 17:38:09 | "Finalizer" daemon prio=8 tid=0x01836400 nid=0x329c in Object.wait() [0x03def000]
2014/05/18 17:38:09 |    java.lang.Thread.State: WAITING (on object monitor)
2014/05/18 17:38:09 | 	at java.lang.Object.wait(Native Method)
2014/05/18 17:38:09 | 	at java.lang.ref.ReferenceQueue.remove(Unknown Source)
2014/05/18 17:38:09 | 	- locked <0x1e9621b8> (a java.lang.ref.ReferenceQueue$Lock)
2014/05/18 17:38:09 | 	at java.lang.ref.ReferenceQueue.remove(Unknown Source)
2014/05/18 17:38:09 | 	at java.lang.ref.Finalizer$FinalizerThread.run(Unknown Source)
2014/05/18 17:38:09 | 
2014/05/18 17:38:09 | "Reference Handler" daemon prio=10 tid=0x01831400 nid=0x3158 in Object.wait() [0x03c3f000]
2014/05/18 17:38:09 |    java.lang.Thread.State: WAITING (on object monitor)
2014/05/18 17:38:09 | 	at java.lang.Object.wait(Native Method)
2014/05/18 17:38:09 | 	at java.lang.Object.wait(Object.java:503)
2014/05/18 17:38:09 | 	at java.lang.ref.Reference$ReferenceHandler.run(Unknown Source)
2014/05/18 17:38:09 | 	- locked <0x1e962240> (a java.lang.ref.Reference$Lock)
2014/05/18 17:38:09 | 
2014/05/18 17:38:09 | "VM Thread" prio=10 tid=0x0182fc00 nid=0x3288 runnable 
2014/05/18 17:38:09 | 
2014/05/18 17:38:09 | "VM Periodic Task Thread" prio=10 tid=0x018d8000 nid=0x2100 waiting on condition 
2014/05/18 17:38:09 | 
2014/05/18 17:38:09 | JNI global references: 321
2014/05/18 17:38:09 | 
2014/05/18 17:38:09 | 
2014/05/18 17:38:09 | Found one Java-level deadlock:
2014/05/18 17:38:09 | =============================
2014/05/18 17:38:09 | "BuildExecutor":
2014/05/18 17:38:09 |   waiting to lock monitor 0x0920e744 (object 0x1f752988, a java.lang.Object),
2014/05/18 17:38:09 |   which is held by "UDP Packet handler 1/1"
2014/05/18 17:38:09 | "UDP Packet handler 1/1":
2014/05/18 17:38:09 |   waiting to lock monitor 0x095bbc34 (object 0x1f752ab8, a java.lang.Object),
2014/05/18 17:38:09 |   which is held by "SimpleScheduler 3/4"
2014/05/18 17:38:09 | "SimpleScheduler 3/4":
2014/05/18 17:38:09 |   waiting to lock monitor 0x090521cc (object 0x1f752a68, a net.i2p.router.transport.udp.UDPTransport$PeerTestEvent),
2014/05/18 17:38:09 |   which is held by "SimpleTimer2 3/4"
2014/05/18 17:38:09 | "SimpleTimer2 3/4":
2014/05/18 17:38:09 |   waiting to lock monitor 0x09059dbc (object 0x1f8380c8, a net.i2p.router.transport.udp.PeerTestManager),
2014/05/18 17:38:09 |   which is held by "SimpleScheduler 3/4"
2014/05/18 17:38:09 | 
2014/05/18 17:38:09 | Java stack information for the threads listed above:
2014/05/18 17:38:09 | ===================================================
2014/05/18 17:38:09 | "BuildExecutor":
2014/05/18 17:38:09 | 	at net.i2p.router.transport.udp.UDPTransport.dropPeer(UDPTransport.java:1306)
2014/05/18 17:38:09 | 	- waiting to lock <0x1f752988> (a java.lang.Object)
2014/05/18 17:38:09 | 	at net.i2p.router.transport.udp.UDPTransport.send(UDPTransport.java:1656)
2014/05/18 17:38:09 | 	at net.i2p.router.transport.GetBidsJob.getBids(GetBidsJob.java:83)
2014/05/18 17:38:09 | 	at net.i2p.router.transport.CommSystemFacadeImpl.processMessage(CommSystemFacadeImpl.java:137)
2014/05/18 17:38:09 | 	at net.i2p.router.OutNetMessagePool.add(OutNetMessagePool.java:49)
2014/05/18 17:38:09 | 	at net.i2p.router.tunnel.pool.BuildRequestor.request(BuildRequestor.java:215)
2014/05/18 17:38:09 | 	at net.i2p.router.tunnel.pool.BuildExecutor.buildTunnel(BuildExecutor.java:483)
2014/05/18 17:38:09 | 	at net.i2p.router.tunnel.pool.BuildExecutor.run(BuildExecutor.java:374)
2014/05/18 17:38:09 | 	at java.lang.Thread.run(Unknown Source)
2014/05/18 17:38:09 | 	at net.i2p.util.I2PThread.run(I2PThread.java:84)
2014/05/18 17:38:09 | "UDP Packet handler 1/1":
2014/05/18 17:38:09 | 	at net.i2p.router.transport.udp.UDPTransport.locked_addRemotePeerState(UDPTransport.java:1165)
2014/05/18 17:38:09 | 	- waiting to lock <0x1f752ab8> (a java.lang.Object)
2014/05/18 17:38:09 | 	at net.i2p.router.transport.udp.UDPTransport.addRemotePeerState(UDPTransport.java:1087)
2014/05/18 17:38:09 | 	- locked <0x1f752988> (a java.lang.Object)
2014/05/18 17:38:09 | 	at net.i2p.router.transport.udp.EstablishmentManager.handleCompletelyEstablished(EstablishmentManager.java:806)
2014/05/18 17:38:09 | 	at net.i2p.router.transport.udp.EstablishmentManager.receiveData(EstablishmentManager.java:611)
2014/05/18 17:38:09 | 	at net.i2p.router.transport.udp.PacketHandler$Handler.handlePacket(PacketHandler.java:691)
2014/05/18 17:38:09 | 	at net.i2p.router.transport.udp.PacketHandler$Handler.receivePacket(PacketHandler.java:564)
2014/05/18 17:38:09 | 	at net.i2p.router.transport.udp.PacketHandler$Handler.handlePacket(PacketHandler.java:300)
2014/05/18 17:38:09 | 	at net.i2p.router.transport.udp.PacketHandler$Handler.run(PacketHandler.java:213)
2014/05/18 17:38:09 | 	at java.lang.Thread.run(Unknown Source)
2014/05/18 17:38:09 | 	at net.i2p.util.I2PThread.run(I2PThread.java:84)
2014/05/18 17:38:09 | "SimpleScheduler 3/4":
2014/05/18 17:38:09 | 	at net.i2p.router.transport.udp.UDPTransport$PeerTestEvent.setLastTested(UDPTransport.java:3201)
2014/05/18 17:38:09 | 	- waiting to lock <0x1f752a68> (a net.i2p.router.transport.udp.UDPTransport$PeerTestEvent)
2014/05/18 17:38:09 | 	at net.i2p.router.transport.udp.UDPTransport.locked_setReachabilityStatus(UDPTransport.java:3022)
2014/05/18 17:38:09 | 	at net.i2p.router.transport.udp.UDPTransport.setReachabilityStatus(UDPTransport.java:2978)
2014/05/18 17:38:09 | 	- locked <0x1f752ab8> (a java.lang.Object)
2014/05/18 17:38:09 | 	at net.i2p.router.transport.udp.PeerTestManager.honorStatus(PeerTestManager.java:482)
2014/05/18 17:38:09 | 	at net.i2p.router.transport.udp.PeerTestManager.testComplete(PeerTestManager.java:469)
2014/05/18 17:38:09 | 	at net.i2p.router.transport.udp.PeerTestManager.access$200(PeerTestManager.java:120)
2014/05/18 17:38:09 | 	at net.i2p.router.transport.udp.PeerTestManager$ContinueTest.timeReached(PeerTestManager.java:226)
2014/05/18 17:38:09 | 	- locked <0x1f8380c8> (a net.i2p.router.transport.udp.PeerTestManager)
2014/05/18 17:38:09 | 	at net.i2p.util.SimpleScheduler$RunnableEvent.run(SimpleScheduler.java:168)
2014/05/18 17:38:09 | 	at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
2014/05/18 17:38:09 | 	at java.util.concurrent.FutureTask.run(Unknown Source)
2014/05/18 17:38:09 | 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(Unknown Source)
2014/05/18 17:38:09 | 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)
2014/05/18 17:38:09 | 	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
2014/05/18 17:38:09 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
2014/05/18 17:38:09 | 	at java.lang.Thread.run(Unknown Source)
2014/05/18 17:38:09 | "SimpleTimer2 3/4":
2014/05/18 17:38:09 | 	at net.i2p.router.transport.udp.PeerTestManager.runTest(PeerTestManager.java:179)
2014/05/18 17:38:09 | 	- waiting to lock <0x1f8380c8> (a net.i2p.router.transport.udp.PeerTestManager)
2014/05/18 17:38:09 | 	at net.i2p.router.transport.udp.UDPTransport$PeerTestEvent.locked_runTest(UDPTransport.java:3155)
2014/05/18 17:38:09 | 	at net.i2p.router.transport.udp.UDPTransport$PeerTestEvent.timeReached(UDPTransport.java:3141)
2014/05/18 17:38:09 | 	- locked <0x1f752a68> (a net.i2p.router.transport.udp.UDPTransport$PeerTestEvent)
2014/05/18 17:38:09 | 	at net.i2p.util.SimpleTimer2$TimedEvent.run(SimpleTimer2.java:346)
2014/05/18 17:38:09 | 	at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
2014/05/18 17:38:09 | 	at java.util.concurrent.FutureTask.run(Unknown Source)
2014/05/18 17:38:09 | 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(Unknown Source)
2014/05/18 17:38:09 | 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)
2014/05/18 17:38:09 | 	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
2014/05/18 17:38:09 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
2014/05/18 17:38:09 | 	at java.lang.Thread.run(Unknown Source)
2014/05/18 17:38:09 | 
2014/05/18 17:38:09 | Found 1 deadlock.
2014/05/18 17:38:09 | 
2014/05/18 17:38:09 | Heap
2014/05/18 17:38:09 |  def new generation   total 80512K, used 32954K [0x13e80000, 0x195d0000, 0x1e920000)
2014/05/18 17:38:09 |   eden space 71616K,  39% used [0x13e80000, 0x15a1ef58, 0x18470000)
2014/05/18 17:38:09 |   from space 8896K,  52% used [0x18470000, 0x188ffaf8, 0x18d20000)
2014/05/18 17:38:09 |   to   space 8896K,   0% used [0x18d20000, 0x18d20000, 0x195d0000)
2014/05/18 17:38:09 |  tenured generation   total 178528K, used 136454K [0x1e920000, 0x29778000, 0x33e80000)
2014/05/18 17:38:09 |    the space 178528K,  76% used [0x1e920000, 0x26e61880, 0x26e61a00, 0x29778000)
2014/05/18 17:38:09 |  compacting perm gen  total 16640K, used 16391K [0x33e80000, 0x34ec0000, 0x37e80000)
2014/05/18 17:38:09 |    the space 16640K,  98% used [0x33e80000, 0x34e81ec0, 0x34e82000, 0x34ec0000)
2014/05/18 17:38:09 |     ro space 10240K,  41% used [0x37e80000, 0x382b24a8, 0x382b2600, 0x38880000)
2014/05/18 17:38:09 |     rw space 12288K,  52% used [0x38880000, 0x38ec6da8, 0x38ec6e00, 0x39480000)

Subtickets

Change History (4)

comment:1 Changed 6 years ago by user

I2P version: 0.9.12-21-rc
Java version: Oracle Corporation 1.7.0_55 (Java™ SE Runtime Environment 1.7.0_55-b14)
Wrapper version: 3.5.22
Server version: 8.1.14.v20131031
Servlet version: Jasper JSP 2.1 Engine
Platform: Windows Vista x86 6.0
Processor: Core 2 (Conroe) (core2)
Jbigi: Locally optimized native BigInteger? library loaded from file
Encoding: Cp1252
Charset: windows-1252

comment:2 Changed 6 years ago by zzz

Component: router/generalrouter/transport
Milestone: 0.9.140.9.13
Owner: set to zzz
Priority: majorblocker

comment:3 Changed 6 years ago by zzz

Status: newtesting

Hopefully fixed in bc06e9bd75809b4ebfe495f18045e1f3299afa6c 0.9.12-22-rc

Introduced in late April, 0.9.12-13 or -14, with new locking in PeerTestEvent?. PeerTestEvent? locked PeerTestManager? and vice versa. BuildExecutor? and UDPPacketHandler were innocently caught in the crossfire. The addDropLock and rebuildLock appear to be OK. Still reviewing to make sure.

comment:4 Changed 5 years ago by zzz

Resolution: fixed
Status: testingclosed
Note: See TracTickets for help on using tickets.