New subject: [JBoss JIRA] Assigned: (ISPN-373) Deadlock between lock and put under heavy concurrency

Monday, 15 March 2010

Deadlock between lock and put under heavy concurrency
-----------------------------------------------------

                 Key: ISPN-373
                 URL: https://jira.jboss.org/jira/browse/ISPN-373
             Project: Infinispan
          Issue Type: Bug
          Components: Locking and Concurrency
    Affects Versions: 4.0.0.Final
         Environment: Mac OS-X 10.6, 2.8Ghz Core 2, 8GB RAM
            Reporter: Nigel Slack-Smith
            Assignee: Manik Surtani

Concurrent calls to lock and then put seem to be deadlocking. After AdvancedCache.lock is
called under a transaction a subsequent call to Cache.put on the same key normally does
not attempt to take out a lock, but after a variable number of concurrent calls Cache.put
is attempting to take out a lock and then deadlocking with the AdvancedCache.lock call. 

Here's my test case which hits the deadlock.

public class DataGridTest {
	@Test
	public void testCreate() {
		CacheManager cacheManager = new DefaultCacheManager();
		final String cacheName = "TestCache";

		Configuration config = new Configuration();
		config.setTransactionManagerLookupClass("org.infinispan.transaction.lookup.DummyTransactionManagerLookup");

		cacheManager.defineConfiguration(cacheName, config);

		final Cache<Object, Object> cache = cacheManager.getCache(cacheName);
		cache.start();

		ExecutorService executorService = Executors.newFixedThreadPool(2);
		for (int i = 0; i < 1000000; ++i) {
			final String valueStr = "V" + i;

			executorService.execute(new Runnable() {
				@Override
				public void run() {
					TransactionManager txnMgr = cache.getAdvancedCache().getTransactionManager();

					try {
						txnMgr.begin();
					} catch (Exception e) {
						fail(e.getMessage());
					}

					cache.getAdvancedCache().lock("K1");
					cache.put("K1", valueStr);

					try {
						txnMgr.commit();
					} catch (Exception e) {
						fail(e.getMessage());
					}
				}
			});
		}

		executorService.shutdown();
		try {
			if (executorService.awaitTermination(300, TimeUnit.SECONDS) == false) {
				fail("Termination timeout");
			}
		} catch (InterruptedException e) {
			fail("Thread interrupted exception: " + e.getMessage());
		}
	}
}

...and here's the stack trace showing what appears to be a deadlock timeout.

2010-03-16 08:35:57,821 1     ERROR
[org.infinispan.interceptors.InvocationContextInterceptor] Execution error: 
org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [10 seconds]
on key [K1] for requestor [GlobalTransaction:<null>:114691]! Lock held by
[GlobalTransaction:<null>:114690]
	at org.infinispan.container.EntryFactoryImpl.acquireLock(EntryFactoryImpl.java:213)
	at
org.infinispan.container.EntryFactoryImpl.wrapEntryForWriting(EntryFactoryImpl.java:148)
	at
org.infinispan.container.EntryFactoryImpl.wrapEntryForWriting(EntryFactoryImpl.java:106)
	at
org.infinispan.interceptors.LockingInterceptor.visitPutKeyValueCommand(LockingInterceptor.java:197)
	at
org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
	at
org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
	at
org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:132)
	at
org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:57)
	at
org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
	at
org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
	at
org.infinispan.interceptors.TxInterceptor.enlistWriteAndInvokeNext(TxInterceptor.java:183)
	at
org.infinispan.interceptors.TxInterceptor.visitPutKeyValueCommand(TxInterceptor.java:132)
	at
org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
	at
org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
	at
org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:48)
	at
org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:34)
	at
org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:57)
	at
org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
	at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:269)
	at org.infinispan.CacheDelegate.put(CacheDelegate.java:434)
	at org.infinispan.CacheDelegate.put(CacheDelegate.java:205)
	at com.kasm.core.test.DataGridTest$1.run(DataGridTest.java:47)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:637)
2010-03-16 08:35:57,821 1     ERROR
[org.infinispan.interceptors.InvocationContextInterceptor] Execution error: 
org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [10 seconds]
on key [K1] for requestor [GlobalTransaction:<null>:114692]! Lock held by
[GlobalTransaction:<null>:114690]
	at org.infinispan.container.EntryFactoryImpl.acquireLock(EntryFactoryImpl.java:213)
	at
org.infinispan.container.EntryFactoryImpl.wrapEntryForWriting(EntryFactoryImpl.java:148)
	at
org.infinispan.container.EntryFactoryImpl.wrapEntryForWriting(EntryFactoryImpl.java:106)
	at
org.infinispan.interceptors.LockingInterceptor.visitLockControlCommand(LockingInterceptor.java:146)
	at
org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:82)
	at
org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
	at
org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:132)
	at
org.infinispan.commands.AbstractVisitor.visitLockControlCommand(AbstractVisitor.java:147)
	at
org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:82)
	at
org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
	at
org.infinispan.interceptors.TxInterceptor.enlistReadAndInvokeNext(TxInterceptor.java:171)
	at
org.infinispan.interceptors.TxInterceptor.visitLockControlCommand(TxInterceptor.java:115)
	at
org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:82)
	at
org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
	at
org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:48)
	at
org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:34)
	at
org.infinispan.commands.AbstractVisitor.visitLockControlCommand(AbstractVisitor.java:147)
	at
org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:82)
	at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:269)
	at org.infinispan.CacheDelegate.lock(CacheDelegate.java:305)
	at org.infinispan.CacheDelegate.lock(CacheDelegate.java:298)
	at com.kasm.core.test.DataGridTest$1.run(DataGridTest.java:46)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:637)
Exception in thread "pool-2-thread-2"
org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [10 seconds]
on key [K1] for requestor [GlobalTransaction:<null>:114691]! Lock held by
[GlobalTransaction:<null>:114690]
	at org.infinispan.container.EntryFactoryImpl.acquireLock(EntryFactoryImpl.java:213)
	at
org.infinispan.container.EntryFactoryImpl.wrapEntryForWriting(EntryFactoryImpl.java:148)
	at
org.infinispan.container.EntryFactoryImpl.wrapEntryForWriting(EntryFactoryImpl.java:106)
	at
org.infinispan.interceptors.LockingInterceptor.visitPutKeyValueCommand(LockingInterceptor.java:197)
	at
org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
	at
org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
	at
org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:132)
	at
org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:57)
	at
org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
	at
org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
	at
org.infinispan.interceptors.TxInterceptor.enlistWriteAndInvokeNext(TxInterceptor.java:183)
	at
org.infinispan.interceptors.TxInterceptor.visitPutKeyValueCommand(TxInterceptor.java:132)
	at
org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
	at
org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
	at
org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:48)
	at
org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:34)
	at
org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:57)
	at
org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
	at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:269)
	at org.infinispan.CacheDelegate.put(CacheDelegate.java:434)
	at org.infinispan.CacheDelegate.put(CacheDelegate.java:205)
	at com.kasm.core.test.DataGridTest$1.run(DataGridTest.java:47)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:637)
Exception in thread "pool-2-thread-1"
org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [10 seconds]
on key [K1] for requestor [GlobalTransaction:<null>:114692]! Lock held by
[GlobalTransaction:<null>:114690]
	at org.infinispan.container.EntryFactoryImpl.acquireLock(EntryFactoryImpl.java:213)
	at
org.infinispan.container.EntryFactoryImpl.wrapEntryForWriting(EntryFactoryImpl.java:148)
	at
org.infinispan.container.EntryFactoryImpl.wrapEntryForWriting(EntryFactoryImpl.java:106)
	at
org.infinispan.interceptors.LockingInterceptor.visitLockControlCommand(LockingInterceptor.java:146)
	at
org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:82)
	at
org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
	at
org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:132)
	at
org.infinispan.commands.AbstractVisitor.visitLockControlCommand(AbstractVisitor.java:147)
	at
org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:82)
	at
org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
	at
org.infinispan.interceptors.TxInterceptor.enlistReadAndInvokeNext(TxInterceptor.java:171)
	at
org.infinispan.interceptors.TxInterceptor.visitLockControlCommand(TxInterceptor.java:115)
	at
org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:82)
	at
org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
	at
org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:48)
	at
org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:34)
	at
org.infinispan.commands.AbstractVisitor.visitLockControlCommand(AbstractVisitor.java:147)
	at
org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:82)
	at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:269)
	at org.infinispan.CacheDelegate.lock(CacheDelegate.java:305)
	at org.infinispan.CacheDelegate.lock(CacheDelegate.java:298)
	at com.kasm.core.test.DataGridTest$1.run(DataGridTest.java:46)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:637)

-- 
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators:
https://jira.jboss.org/jira/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011

2010

2009

[JBoss JIRA] Created: (ISPN-373) Deadlock between lock and put under heavy concurrency