Re: [jgroups-users] Locks get locked forever after a cluster members leaves
Questions/problems related to using JGroups <[email protected]> Mon, 23 Oct 2017 14:50:01 +0200
| Newsgroups | gmane.comp.java.javagroups.general |
|---|---|
| Message-ID | <mailman.16706.1508763012.12770.javagroups-users@lists.sourceforge.net> |
So if we look at the server locks only for server locks only for lock
'writelock/regular/instance_2_1/', we can see that the lock is held by
node 40388 with thread-id=369 (shortened node names):
writelock/regular/instance_2_1/:
40388::369,
queue:
L(writelock/regular/instance_2_1/,40388::373)
TL(writelock/regular/instance_2_1/,45507::413,20000)
Thread 373 on the same node has also issued a lock() and is waiting in
the queue for the lock to be released by 369.
The client locks show that the lock is owned by 369
my locks:
writelock/regular/instance_2_1/
(40388::369, 40388::373, unlocked)
Now thread 369 calls unlock() [I assume?].
The server locks are correctly changed:
server locks:
writelock/regular/instance_2_1/: 40388::373
We can see that 369 has released the lock and the next thread in the
queue (373) has acquired the lock. There are no pending lock requests,
as 413 timed out on its tryLock().
However, the client side lock table is incorrect:
my locks:
writelock/regular/instance_2_1/ (40388::369, 40388::373,
40388::45, unlocked),
We can see that 369 has not yet been removed (it should have!) and yet
373 does hold the lock (no 'unlocked' shown)!
I need to investigate further. Questions:
#1 What's your configuration? I assume you don't use FORK do you?
#2 I assume use_thread_id_for_lock_owner has not been set to false
(default: true)?
#3 How does 369 release its lock? Obviously 40388::369 and 40388::373
are 2 threads running in the same member (node), so it must be a
Lock.unlock()? I'm unsure because you mentioned 'the old coordinator
left', but in this case, both 369 *and* 373 would have been released...
On 19/10/17 08:29, Questions/problems related to using JGroups via
javagroups-users wrote:
> I use the central locking protocol extensively (> 10 locks requests per
> second isn't unusual) in our application thats currently running with 5
> cluster members (nodes). I have dead lock issues (e.g. locks that are
> never released) and I think this is a bug / race condition in the
> protocol *somewhere*. I did a lot of debugging but can't pinpoint the
> error so I need some help ;-). The protocol configuration looks like the
> default TCP nio configuration with central locking configured like this:
>
> <CENTRAL_LOCK num_backups="2" />
>
> <COUNTER bypass_bundling="true"
> num_backups="9999"/>
>
> I currently use JGroups 4.0.4.Final but I've seen this is other versions
> too.
>
> It looks like I have these problems when the coordinator of the cluster
> leaves (gracefully). When that happens and a new view is installed I see
> that some locks stay (or get?) locked forever. All locks I use are
> wrapped in what I call a 'logging try lock'. I never use regular lock()
> calls, it's always a trylock with a timeout of 20 seconds. I log *every*
> trylock request (and the result) and unlock() call. Because of that I
> should be able to tell if a lock is acquired but never released. Thats
> not te case so I suspect it has something to do with taking over the
> coordination of the locks.
>
> I have some logs of a situation where node1 (old coördinator) stops and
> node2 becomes the new coördinator. Right after that cluster members fail
> to acquire the lock 'writelock/regular/instance_2_1/' because it doesn't
> get locked within 20 seconds.
>
> Node2 installing a new view after node1 leaves:
>
> 10-18 09:44:36.840 1966180821
> [jgroups-25500,yy,NodeAddress-2_node2-40388] DEBUG
> org.jgroups.protocols.pbcast.GMS - NodeAddress-2_node2-40388: installing
> view [NodeAddress-2_node2-40388|43] (4) [NodeAddress-2_node2-40388,
> NodeAddress-3_node3-45507, NodeAddress-6_node4-63954,
> NodeAddress-7_node5-32742]
> 10-18 09:44:36.841 1966180822
> [jgroups-25500,yy,NodeAddress-2_node2-40388] DEBUG
> org.jgroups.protocols.pbcast.STABLE - resuming message garbage collection
> 10-18 09:44:36.841 1966180822
> [jgroups-25500,yy,NodeAddress-2_node2-40388] DEBUG
> o.jgroups.protocols.pbcast.NAKACK2 - NodeAddress-2_node2-40388: removed
> NodeAddress-1_node1-3442 from xmit_table (not member anymore)
> 10-18 09:44:36.849 1966180830
> [jgroups-25500,yy,NodeAddress-2_node2-40388] DEBUG nl.x.jgroups.c.i.a -
> handling local view change: [NodeAddress-2_node2-40388|43] (4)
> [NodeAddress-2_node2-40388, NodeAddress-3_node3-45507,
> NodeAddress-6_node4-63954, NodeAddress-7_node5-32742]
> ...
> 10-18 09:44:36.884 1966180865
> [jgroups-25500,yy,NodeAddress-2_node2-40388] DEBUG
> org.jgroups.protocols.CENTRAL_LOCK - view=[NodeAddress-2_node2-40388|43]
> (4) [NodeAddress-2_node2-40388, NodeAddress-3_node3-45507,
> NodeAddress-6_node4-63954, NodeAddress-7_node5-32742]
> 10-18 09:44:36.884 1966180865
> [jgroups-25500,yy,NodeAddress-2_node2-40388] DEBUG
> org.jgroups.protocols.CENTRAL_LOCK -
> local_addr=NodeAddress-2_node2-40388, coord=NodeAddress-2_node2-40388,
> is_coord=true
> 10-18 09:44:36.909 1966180890
> [jgroups-25500,yy,NodeAddress-2_node2-40388] DEBUG
> org.jgroups.protocols.COUNTER - view=[NodeAddress-2_node2-40388|43] (4)
> [NodeAddress-2_node2-40388, NodeAddress-3_node3-45507,
> NodeAddress-6_node4-63954, NodeAddress-7_node5-32742]
> 10-18 09:44:36.947 1966180928 [pool-1-thread-514351] WARN
> nl.x.jgroups.b.c - Detected new view!
> 10-18 09:44:36.950 1966180931 [pool-1-thread-514351] WARN
> nl.x.jgroups.b.c - Node NodeAddress-1_node1-3442 left, cancelling any
> pending requests to that node ...
>
> Node2 last lock on 'writelock/regular/instance_2_1/':
>
> 10-18 09:44:01.282 1966145263 [pool-2-thread-7] DEBUG nl.x.util.c.k
> - -2114432549 Thread (84) pool-2-thread-7 acquired
> writelock/regular/instance_2_1/
> 10-18 09:44:01.285 1966145266 [pool-2-thread-7] DEBUG nl.x.util.c.k
> - -2114432549 Thread (84) pool-2-thread-7 is releasing
> writelock/regular/instance_2_1/
> 10-18 09:44:01.285 1966145266 [pool-2-thread-7] DEBUG nl.x.util.c.k
> - -2114432549 Thread (84) pool-2-thread-7 has released
> writelock/regular/instance_2_1/
>
> Node2 first time lock on 'writelock/regular/instance_2_1/' fails:
>
> 10-18 09:45:21.113 1966225094 [pool-2-thread-5] ERROR
> nl.shockmedia.dds.cluster.jgroups.b - Failed aquiring lock Logging lock
> for: writelock/regular/instance_2_1/ [unlocked]. Current lock table:
>
> server locks:
> writelock/regular/instance_2_1/:
> NodeAddress-2_node2-40388::369,
> queue:
> L(writelock/regular/instance_2_1/,NodeAddress-2_node2-40388::373)
> TL(writelock/regular/instance_2_1/,NodeAddress-3_node3-45507::413,20000)
>
> writelock/regular/instance_2_1/31:
> NodeAddress-2_node2-40388::369,
> queue:
> L(writelock/regular/instance_2_1/31,NodeAddress-2_node2-40388::373)
>
> writelock/regular/instance_2_1/3635: NodeAddress-3_node3-45507::413
> writelock/regular/instance_2_1/32: NodeAddress-2_node2-40388::46
>
> my locks:
> writelock/regular/instance_2_1/
> (NodeAddress-2_node2-40388::369,
> NodeAddress-2_node2-40388::373, unlocked),
>
> writelock/regular/instance_2_1/31
> (NodeAddress-2_node2-40388::369,
> NodeAddress-2_node2-40388::373, unlocked),
>
> writelock/regular/instance_2_1/32
> (NodeAddress-2_node2-40388::46)
>
> There is no trace anywhere in the logs where node2 acquires a lock on
> 'writelock/regular/instance_2_1/' and never releases that lock. However
> if I'm correct the log output says that the lock
> 'writelock/regular/instance_2_1/' is currently locked by
> 'NodeAddress-2_node2-40388::369'. This stays like this forever (right?),
> the only solution is to stop all cluster members and start them again.
> This is the output of a failed trylock (not locked within 20 seconds) >
> 1 hour later:
>
> 10-18 10:54:16.682 1970360663 [RxCachedThreadScheduler-3] ERROR
> nl.shockmedia.dds.cluster.jgroups.b - Failed aquiring lock Logging lock
> for: writelock/regular/instance_2_1/ [unlocked]. Current lock table:
> server locks:
> writelock/regular/instance_2_1/: NodeAddress-2_node2-40388::373
> writelock/regular/instance_2_1/3230: NodeAddress-1_node1-6233::120
> writelock/regular/instance_2_1/3434: NodeAddress-2_node2-40388::93
> writelock/regular/instance_2_1/3138: NodeAddress-2_node2-40388::45
> writelock/regular/instance_2_1/31: NodeAddress-2_node2-40388::373
> writelock/regular/instance_2_1/3635: NodeAddress-3_node3-45507::349
> writelock/regular/instance_2_1/3937: NodeAddress-3_node3-45507::95
>
> my locks: writelock/regular/instance_2_1/
> (NodeAddress-2_node2-40388::369, NodeAddress-2_node2-40388::373,
> NodeAddress-2_node2-40388::45, unlocked),
> writelock/regular/instance_2_1/3434 (NodeAddress-2_node2-40388::93),
> writelock/regular/instance_2_1/3138 (NodeAddress-2_node2-40388::45),
> writelock/regular/instance_2_1/31 (NodeAddress-2_node2-40388::369,
> NodeAddress-2_node2-40388::373)
>
> I need some help in debugging this issue. Its not easy to reproduce, I
> don't have this problem everytime I shut-down a node, it happens every
> now and then. Any suggestions?
>
> --
> Met vriendelijke groet / Kind regards,
> Bram Klein Gunnewiek | Shock Media B.V.
>
> Tel: +31 (0)546 - 714360
> Fax: +31 (0)546 - 714361
> Web:https://www.shockmedia.nl/
>
>
>
> ------------------------------------------------------------------------------
> Check out the vibrant tech community on one of the world's most
> engaging tech sites, Slashdot.org! http://sdm.link/slashdot
>
>
>
> _______________________________________________
> javagroups-users mailing list
> [email protected]
> https://lists.sourceforge.net/lists/listinfo/javagroups-users
>
--
Bela Ban | http://www.jgroups.org
------------------------------------------------------------------------------
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot
_______________________________________________
javagroups-users mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/javagroups-users