You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@ignite.apache.org by "Pavel Pereslegin (JIRA)" <ji...@apache.org> on 2017/10/27 15:49:00 UTC
[jira] [Created] (IGNITE-6782) Undetected deadlock on LOCAL cache
with OPTIMISTIC transactions.
Pavel Pereslegin created IGNITE-6782:
----------------------------------------
Summary: Undetected deadlock on LOCAL cache with OPTIMISTIC transactions.
Key: IGNITE-6782
URL: https://issues.apache.org/jira/browse/IGNITE-6782
Project: Ignite
Issue Type: Bug
Security Level: Public (Viewable by anyone)
Components: cache
Reporter: Pavel Pereslegin
It is possible to create a deadlock on LOCAL cache with OPTIMISTIC transactions which will not be tracked by deadlock detection.
Reproducer tries to lock same keys on different threads in reverse order simultaneously.
{code:java}
public class TxOptimisticDeadlockDetectionLocalTest extends GridCommonAbstractTest {
public void test() throws Exception {
CacheConfiguration<Integer, Integer> ccfg = new CacheConfiguration<Integer, Integer>("test")
.setCacheMode(CacheMode.LOCAL)
.setAtomicityMode(CacheAtomicityMode.TRANSACTIONAL);
try (Ignite node = startGrid(0)) {
for (int n = 0; n < 100; n++) {
IgniteCache<Integer, Integer> cache = node.createCache(ccfg);
tryLocks(node, cache, TransactionConcurrency.OPTIMISTIC, TransactionIsolation.REPEATABLE_READ);
cache.destroy();
}
}
}
private void tryLocks(final Ignite ignite, final IgniteCache<Integer, Integer> cache,
final TransactionConcurrency concurrency, final TransactionIsolation isolation) throws Exception {
final AtomicInteger cnt = new AtomicInteger();
final CyclicBarrier barrier = new CyclicBarrier(2);
final Integer[] keys = {1, 2};
GridTestUtils.runMultiThreaded(new Runnable() {
@Override public void run() {
int threadNum = cnt.getAndIncrement();
try (Transaction tx = ignite.transactions().txStart(concurrency, isolation, 500, 0)) {
cache.put(keys[threadNum], 0);
cache.put(keys[1 - threadNum], 0);
U.awaitQuiet(barrier);
tx.commit();
}
}
}, 2, "tx-thread");
}
}
{code}
Usually, threads get stuck on commit in the first iteration.
Typical debug log is shown below:
{noformat}
[509][tx-thread-2][IgniteTxManager] Transaction created: GridNearTxLocal [mappings=IgniteTxMappingsImpl [], nearLocallyMapped=false, colocatedLocallyMapped=false, needCheckBackup=null, hasRemoteLocks=false, trackTimeout=true, thread=tx-thread-2, mappings=IgniteTxMappingsImpl [], super=GridDhtTxLocalAdapter [nearOnOriginatingNode=false, nearNodes=[], dhtNodes=[], explicitLock=false, super=IgniteTxLocalAdapter [completedBase=null, sndTransformedVals=false, depEnabled=false, txState=IgniteTxStateImpl [activeCacheIds=GridIntList [idx=0, arr=[]], recovery=null, txMap=[]], super=IgniteTxAdapter [xidVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], writeVer=null, implicit=false, loc=true, threadId=60, startTime=1509110501490, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, startVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], endVer=null, isolation=READ_COMMITTED, concurrency=OPTIMISTIC, timeout=500, sysInvalidate=false, sys=false, plc=2, commitVer=null, finalizing=NONE, invalidParts=null, state=ACTIVE, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], duration=10ms, onePhaseCommit=false], size=0]]]
[509][tx-thread-1][IgniteTxManager] Transaction created: GridNearTxLocal [mappings=IgniteTxMappingsImpl [], nearLocallyMapped=false, colocatedLocallyMapped=false, needCheckBackup=null, hasRemoteLocks=false, trackTimeout=true, thread=tx-thread-1, mappings=IgniteTxMappingsImpl [], super=GridDhtTxLocalAdapter [nearOnOriginatingNode=false, nearNodes=[], dhtNodes=[], explicitLock=false, super=IgniteTxLocalAdapter [completedBase=null, sndTransformedVals=false, depEnabled=false, txState=IgniteTxStateImpl [activeCacheIds=GridIntList [idx=0, arr=[]], recovery=null, txMap=[]], super=IgniteTxAdapter [xidVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], writeVer=null, implicit=false, loc=true, threadId=59, startTime=1509110501490, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, startVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], endVer=null, isolation=READ_COMMITTED, concurrency=OPTIMISTIC, timeout=500, sysInvalidate=false, sys=false, plc=2, commitVer=null, finalizing=NONE, invalidParts=null, state=ACTIVE, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], duration=10ms, onePhaseCommit=false], size=0]]]
[513][tx-thread-2][IgniteTxManager] Transaction started: GridNearTxLocal [mappings=IgniteTxMappingsImpl [], nearLocallyMapped=false, colocatedLocallyMapped=false, needCheckBackup=null, hasRemoteLocks=false, trackTimeout=true, thread=tx-thread-2, mappings=IgniteTxMappingsImpl [], super=GridDhtTxLocalAdapter [nearOnOriginatingNode=false, nearNodes=[], dhtNodes=[], explicitLock=false, super=IgniteTxLocalAdapter [completedBase=null, sndTransformedVals=false, depEnabled=false, txState=IgniteTxStateImpl [activeCacheIds=GridIntList [idx=0, arr=[]], recovery=null, txMap=[]], super=IgniteTxAdapter [xidVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], writeVer=null, implicit=false, loc=true, threadId=60, startTime=1509110501490, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, startVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], endVer=null, isolation=READ_COMMITTED, concurrency=OPTIMISTIC, timeout=500, sysInvalidate=false, sys=false, plc=2, commitVer=null, finalizing=NONE, invalidParts=null, state=ACTIVE, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], duration=20ms, onePhaseCommit=false], size=0]]]
[513][tx-thread-1][IgniteTxManager] Transaction started: GridNearTxLocal [mappings=IgniteTxMappingsImpl [], nearLocallyMapped=false, colocatedLocallyMapped=false, needCheckBackup=null, hasRemoteLocks=false, trackTimeout=true, thread=tx-thread-1, mappings=IgniteTxMappingsImpl [], super=GridDhtTxLocalAdapter [nearOnOriginatingNode=false, nearNodes=[], dhtNodes=[], explicitLock=false, super=IgniteTxLocalAdapter [completedBase=null, sndTransformedVals=false, depEnabled=false, txState=IgniteTxStateImpl [activeCacheIds=GridIntList [idx=0, arr=[]], recovery=null, txMap=[]], super=IgniteTxAdapter [xidVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], writeVer=null, implicit=false, loc=true, threadId=59, startTime=1509110501490, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, startVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], endVer=null, isolation=READ_COMMITTED, concurrency=OPTIMISTIC, timeout=500, sysInvalidate=false, sys=false, plc=2, commitVer=null, finalizing=NONE, invalidParts=null, state=ACTIVE, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], duration=20ms, onePhaseCommit=false], size=0]]]
[544][tx-thread-2][MemoryEventStorageSpi] Event recorded: CacheEvent [cacheName=test, part=0, key=2, xid=null, lockId=null, newVal=null, oldVal=null, hasOldVal=false, hasNewVal=false, near=false, subjId=null, cloClsName=null, taskName=null, nodeId8=f44e0815, evtNodeId8=f44e0815, msg=Cache event., type=CACHE_ENTRY_CREATED, tstamp=1509110501540]
[544][tx-thread-1][MemoryEventStorageSpi] Event recorded: CacheEvent [cacheName=test, part=0, key=1, xid=null, lockId=null, newVal=null, oldVal=null, hasOldVal=false, hasNewVal=false, near=false, subjId=null, cloClsName=null, taskName=null, nodeId8=f44e0815, evtNodeId8=f44e0815, msg=Cache event., type=CACHE_ENTRY_CREATED, tstamp=1509110501540]
[567][tx-thread-1][GridNearTxLocal] Created transaction entry: IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=NOOP, val=null], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=false, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], val=null, startVer=1509110498766, ver=GridCacheVersion [topVer=120590501, order=1509110498766, nodeOrder=1], hash=1, extras=null, flags=2]], prepared=0, locked=false, nodeId=null, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1]]
[568][tx-thread-2][GridNearTxLocal] Created transaction entry: IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=NOOP, val=null], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=false, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], val=null, startVer=1509110498765, ver=GridCacheVersion [topVer=120590501, order=1509110498765, nodeOrder=1], hash=2, extras=null, flags=2]], prepared=0, locked=false, nodeId=null, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1]]
[570][tx-thread-1][GridNearTxLocal] Created transaction entry: IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=NOOP, val=null], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=false, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], val=null, startVer=1509110498765, ver=GridCacheVersion [topVer=120590501, order=1509110498765, nodeOrder=1], hash=2, extras=null, flags=2]], prepared=0, locked=false, nodeId=null, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1]]
[571][tx-thread-2][GridNearTxLocal] Created transaction entry: IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=NOOP, val=null], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=false, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], val=null, startVer=1509110498766, ver=GridCacheVersion [topVer=120590501, order=1509110498766, nodeOrder=1], hash=1, extras=null, flags=2]], prepared=0, locked=false, nodeId=null, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1]]
[573][tx-thread-1][GridNearTxLocal] Committing near local tx: GridNearTxLocal [mappings=IgniteTxMappingsImpl [], nearLocallyMapped=false, colocatedLocallyMapped=false, needCheckBackup=null, hasRemoteLocks=false, trackTimeout=true, thread=tx-thread-1, mappings=IgniteTxMappingsImpl [], super=GridDhtTxLocalAdapter [nearOnOriginatingNode=false, nearNodes=[], dhtNodes=[], explicitLock=false, super=IgniteTxLocalAdapter [completedBase=null, sndTransformedVals=false, depEnabled=false, txState=IgniteTxStateImpl [activeCacheIds=GridIntList [idx=1, arr=[3556498]], recovery=false, txMap=[IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], val=null, startVer=1509110498765, ver=GridCacheVersion [topVer=120590501, order=1509110498765, nodeOrder=1], hash=2, extras=null, flags=2]], prepared=0, locked=false, nodeId=null, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1]], IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], val=null, startVer=1509110498766, ver=GridCacheVersion [topVer=120590501, order=1509110498766, nodeOrder=1], hash=1, extras=null, flags=2]], prepared=0, locked=false, nodeId=null, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1]]]], super=IgniteTxAdapter [xidVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], writeVer=null, implicit=false, loc=true, threadId=59, startTime=1509110501490, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, startVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], endVer=null, isolation=READ_COMMITTED, concurrency=OPTIMISTIC, timeout=500, sysInvalidate=false, sys=false, plc=2, commitVer=null, finalizing=NONE, invalidParts=null, state=ACTIVE, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], duration=81ms, onePhaseCommit=false], size=2]]]
[574][tx-thread-2][GridNearTxLocal] Committing near local tx: GridNearTxLocal [mappings=IgniteTxMappingsImpl [], nearLocallyMapped=false, colocatedLocallyMapped=false, needCheckBackup=null, hasRemoteLocks=false, trackTimeout=true, thread=tx-thread-2, mappings=IgniteTxMappingsImpl [], super=GridDhtTxLocalAdapter [nearOnOriginatingNode=false, nearNodes=[], dhtNodes=[], explicitLock=false, super=IgniteTxLocalAdapter [completedBase=null, sndTransformedVals=false, depEnabled=false, txState=IgniteTxStateImpl [activeCacheIds=GridIntList [idx=1, arr=[3556498]], recovery=false, txMap=[IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], val=null, startVer=1509110498766, ver=GridCacheVersion [topVer=120590501, order=1509110498766, nodeOrder=1], hash=1, extras=null, flags=2]], prepared=0, locked=false, nodeId=null, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1]], IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], val=null, startVer=1509110498765, ver=GridCacheVersion [topVer=120590501, order=1509110498765, nodeOrder=1], hash=2, extras=null, flags=2]], prepared=0, locked=false, nodeId=null, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1]]]], super=IgniteTxAdapter [xidVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], writeVer=null, implicit=false, loc=true, threadId=60, startTime=1509110501490, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, startVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], endVer=null, isolation=READ_COMMITTED, concurrency=OPTIMISTIC, timeout=500, sysInvalidate=false, sys=false, plc=2, commitVer=null, finalizing=NONE, invalidParts=null, state=ACTIVE, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], duration=81ms, onePhaseCommit=false], size=2]]]
[596][tx-thread-2][GridCacheMvccManager] Added future to future map: GridNearOptimisticTxPrepareFuture [miniId=0, txMapping=null, innerFuts=[], keyLockFut=null, tx=GridNearTxLocal [mappings=IgniteTxMappingsImpl [], nearLocallyMapped=false, colocatedLocallyMapped=false, needCheckBackup=null, hasRemoteLocks=false, trackTimeout=true, thread=tx-thread-2, mappings=IgniteTxMappingsImpl [], super=GridDhtTxLocalAdapter [nearOnOriginatingNode=false, nearNodes=[], dhtNodes=[], explicitLock=false, super=IgniteTxLocalAdapter [completedBase=null, sndTransformedVals=false, depEnabled=false, txState=IgniteTxStateImpl [activeCacheIds=GridIntList [idx=1, arr=[3556498]], recovery=false, txMap=[IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], val=null, startVer=1509110498766, ver=GridCacheVersion [topVer=120590501, order=1509110498766, nodeOrder=1], hash=1, extras=null, flags=2]], prepared=0, locked=false, nodeId=null, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1]], IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], val=null, startVer=1509110498765, ver=GridCacheVersion [topVer=120590501, order=1509110498765, nodeOrder=1], hash=2, extras=null, flags=2]], prepared=0, locked=false, nodeId=null, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1]]]], super=IgniteTxAdapter [xidVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], writeVer=null, implicit=false, loc=true, threadId=60, startTime=1509110501490, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, startVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], endVer=null, isolation=READ_COMMITTED, concurrency=OPTIMISTIC, timeout=500, sysInvalidate=false, sys=false, plc=2, commitVer=null, finalizing=NONE, invalidParts=null, state=ACTIVE, topVer=AffinityTopologyVersion [topVer=1, minorTopVer=1], duration=101ms, onePhaseCommit=false], size=2]]], super=GridCompoundFuture [rdc=org.apache.ignite.internal.processors.cache.distributed.near.GridNearTxPrepareFutureAdapter$1@5a6efc31, initFlag=0, lsnrCalls=0, done=false, cancelled=false, err=null, futs=[]]]
[597][tx-thread-1][GridCacheMvccManager] Added future to future map: GridNearOptimisticTxPrepareFuture [miniId=0, txMapping=null, innerFuts=[], keyLockFut=null, tx=GridNearTxLocal [mappings=IgniteTxMappingsImpl [], nearLocallyMapped=false, colocatedLocallyMapped=false, needCheckBackup=null, hasRemoteLocks=false, trackTimeout=true, thread=tx-thread-1, mappings=IgniteTxMappingsImpl [], super=GridDhtTxLocalAdapter [nearOnOriginatingNode=false, nearNodes=[], dhtNodes=[], explicitLock=false, super=IgniteTxLocalAdapter [completedBase=null, sndTransformedVals=false, depEnabled=false, txState=IgniteTxStateImpl [activeCacheIds=GridIntList [idx=1, arr=[3556498]], recovery=false, txMap=[IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], val=null, startVer=1509110498765, ver=GridCacheVersion [topVer=120590501, order=1509110498765, nodeOrder=1], hash=2, extras=null, flags=2]], prepared=0, locked=false, nodeId=null, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1]], IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], val=null, startVer=1509110498766, ver=GridCacheVersion [topVer=120590501, order=1509110498766, nodeOrder=1], hash=1, extras=null, flags=2]], prepared=0, locked=false, nodeId=null, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1]]]], super=IgniteTxAdapter [xidVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], writeVer=null, implicit=false, loc=true, threadId=59, startTime=1509110501490, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, startVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], endVer=null, isolation=READ_COMMITTED, concurrency=OPTIMISTIC, timeout=500, sysInvalidate=false, sys=false, plc=2, commitVer=null, finalizing=NONE, invalidParts=null, state=ACTIVE, topVer=AffinityTopologyVersion [topVer=1, minorTopVer=1], duration=101ms, onePhaseCommit=false], size=2]]], super=GridCompoundFuture [rdc=org.apache.ignite.internal.processors.cache.distributed.near.GridNearTxPrepareFutureAdapter$1@5a6efc31, initFlag=0, lsnrCalls=0, done=false, cancelled=false, err=null, futs=[]]]
[599][tx-thread-2][GridNearTxLocal] Changed transaction state [prev=ACTIVE, new=PREPARING, tx=GridNearTxLocal [mappings=IgniteTxMappingsImpl [], nearLocallyMapped=false, colocatedLocallyMapped=false, needCheckBackup=null, hasRemoteLocks=false, trackTimeout=true, thread=tx-thread-2, mappings=IgniteTxMappingsImpl [], super=GridDhtTxLocalAdapter [nearOnOriginatingNode=false, nearNodes=[], dhtNodes=[], explicitLock=false, super=IgniteTxLocalAdapter [completedBase=null, sndTransformedVals=false, depEnabled=false, txState=IgniteTxStateImpl [activeCacheIds=GridIntList [idx=1, arr=[3556498]], recovery=false, txMap=[IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], val=null, startVer=1509110498766, ver=GridCacheVersion [topVer=120590501, order=1509110498766, nodeOrder=1], hash=1, extras=null, flags=2]], prepared=0, locked=false, nodeId=null, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1]], IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], val=null, startVer=1509110498765, ver=GridCacheVersion [topVer=120590501, order=1509110498765, nodeOrder=1], hash=2, extras=null, flags=2]], prepared=0, locked=false, nodeId=null, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1]]]], super=IgniteTxAdapter [xidVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], writeVer=null, implicit=false, loc=true, threadId=60, startTime=1509110501490, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, startVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], endVer=null, isolation=READ_COMMITTED, concurrency=OPTIMISTIC, timeout=500, sysInvalidate=false, sys=false, plc=2, commitVer=null, finalizing=NONE, invalidParts=null, state=PREPARING, topVer=AffinityTopologyVersion [topVer=1, minorTopVer=1], duration=101ms, onePhaseCommit=false], size=2]]]]
[602][tx-thread-1][GridNearTxLocal] Changed transaction state [prev=ACTIVE, new=PREPARING, tx=GridNearTxLocal [mappings=IgniteTxMappingsImpl [], nearLocallyMapped=false, colocatedLocallyMapped=false, needCheckBackup=null, hasRemoteLocks=false, trackTimeout=true, thread=tx-thread-1, mappings=IgniteTxMappingsImpl [], super=GridDhtTxLocalAdapter [nearOnOriginatingNode=false, nearNodes=[], dhtNodes=[], explicitLock=false, super=IgniteTxLocalAdapter [completedBase=null, sndTransformedVals=false, depEnabled=false, txState=IgniteTxStateImpl [activeCacheIds=GridIntList [idx=1, arr=[3556498]], recovery=false, txMap=[IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], val=null, startVer=1509110498765, ver=GridCacheVersion [topVer=120590501, order=1509110498765, nodeOrder=1], hash=2, extras=null, flags=2]], prepared=0, locked=false, nodeId=null, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1]], IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], val=null, startVer=1509110498766, ver=GridCacheVersion [topVer=120590501, order=1509110498766, nodeOrder=1], hash=1, extras=null, flags=2]], prepared=0, locked=false, nodeId=null, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1]]]], super=IgniteTxAdapter [xidVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], writeVer=null, implicit=false, loc=true, threadId=59, startTime=1509110501490, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, startVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], endVer=null, isolation=READ_COMMITTED, concurrency=OPTIMISTIC, timeout=500, sysInvalidate=false, sys=false, plc=2, commitVer=null, finalizing=NONE, invalidParts=null, state=PREPARING, topVer=AffinityTopologyVersion [topVer=1, minorTopVer=1], duration=111ms, onePhaseCommit=false], size=2]]]]
[603][tx-thread-2][GridNearTxPrepareFutureAdapter] Mapped key to primary node [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], part=0, primary=ClusterNode [id=f44e0815-5711-4b98-8a26-4f9ae6000000, order=1, addr=[127.0.0.1], daemon=false], topVer=AffinityTopologyVersion [topVer=1, minorTopVer=1]]
[606][tx-thread-1][GridNearTxPrepareFutureAdapter] Mapped key to primary node [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], part=0, primary=ClusterNode [id=f44e0815-5711-4b98-8a26-4f9ae6000000, order=1, addr=[127.0.0.1], daemon=false], topVer=AffinityTopologyVersion [topVer=1, minorTopVer=1]]
[609][tx-thread-1][GridNearTxPrepareFutureAdapter] Mapped key to primary node [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], part=0, primary=ClusterNode [id=f44e0815-5711-4b98-8a26-4f9ae6000000, order=1, addr=[127.0.0.1], daemon=false], topVer=AffinityTopologyVersion [topVer=1, minorTopVer=1]]
[609][tx-thread-2][GridNearTxPrepareFutureAdapter] Mapped key to primary node [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], part=0, primary=ClusterNode [id=f44e0815-5711-4b98-8a26-4f9ae6000000, order=1, addr=[127.0.0.1], daemon=false], topVer=AffinityTopologyVersion [topVer=1, minorTopVer=1]]
[610][tx-thread-1][GridNearTxPrepareFutureAdapter] Still waiting for locks [fut=KeyLockFuture [lockKeys=GridConcurrentHashSet [elements=[IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498], IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498]]], allKeysAdded=true, super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=1188433266]], keys=GridConcurrentHashSet [elements=[IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498], IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498]]]]
[610][tx-thread-2][GridNearTxPrepareFutureAdapter] Still waiting for locks [fut=KeyLockFuture [lockKeys=GridConcurrentHashSet [elements=[IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498], IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498]]], allKeysAdded=true, super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=355191933]], keys=GridConcurrentHashSet [elements=[IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498], IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498]]]]
[613][tx-thread-1][GridNearTxLocal] Added mappings to transaction [locId=f44e0815-5711-4b98-8a26-4f9ae6000000, mappings=[GridDistributedTxMapping [entries=[IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], val=null, startVer=1509110498766, ver=GridCacheVersion [topVer=120590501, order=1509110498766, nodeOrder=1], hash=1, extras=null, flags=2]], prepared=0, locked=false, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1]], IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], val=null, startVer=1509110498765, ver=GridCacheVersion [topVer=120590501, order=1509110498765, nodeOrder=1], hash=2, extras=null, flags=2]], prepared=0, locked=false, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1]]], explicitLock=false, dhtVer=null, last=true, nearEntries=0, clientFirst=false, node=f44e0815-5711-4b98-8a26-4f9ae6000000]], tx=GridNearTxLocal [mappings=IgniteTxMappingsImpl [], nearLocallyMapped=false, colocatedLocallyMapped=false, needCheckBackup=null, hasRemoteLocks=false, trackTimeout=true, thread=tx-thread-1, mappings=IgniteTxMappingsImpl [], super=GridDhtTxLocalAdapter [nearOnOriginatingNode=false, nearNodes=[], dhtNodes=[], explicitLock=false, super=IgniteTxLocalAdapter [completedBase=null, sndTransformedVals=false, depEnabled=false, txState=IgniteTxStateImpl [activeCacheIds=GridIntList [idx=1, arr=[3556498]], recovery=false, txMap=[IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], val=null, startVer=1509110498765, ver=GridCacheVersion [topVer=120590501, order=1509110498765, nodeOrder=1], hash=2, extras=null, flags=2]], prepared=0, locked=false, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1]], IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], val=null, startVer=1509110498766, ver=GridCacheVersion [topVer=120590501, order=1509110498766, nodeOrder=1], hash=1, extras=null, flags=2]], prepared=0, locked=false, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1]]]], super=IgniteTxAdapter [xidVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], writeVer=null, implicit=false, loc=true, threadId=59, startTime=1509110501490, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, startVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], endVer=null, isolation=READ_COMMITTED, concurrency=OPTIMISTIC, timeout=500, sysInvalidate=false, sys=false, plc=2, commitVer=null, finalizing=NONE, invalidParts=null, state=PREPARING, topVer=AffinityTopologyVersion [topVer=1, minorTopVer=1], duration=121ms, onePhaseCommit=false], size=2]]]]
[613][tx-thread-2][GridNearTxLocal] Added mappings to transaction [locId=f44e0815-5711-4b98-8a26-4f9ae6000000, mappings=[GridDistributedTxMapping [entries=[IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], val=null, startVer=1509110498765, ver=GridCacheVersion [topVer=120590501, order=1509110498765, nodeOrder=1], hash=2, extras=null, flags=2]], prepared=0, locked=false, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1]], IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], val=null, startVer=1509110498766, ver=GridCacheVersion [topVer=120590501, order=1509110498766, nodeOrder=1], hash=1, extras=null, flags=2]], prepared=0, locked=false, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1]]], explicitLock=false, dhtVer=null, last=true, nearEntries=0, clientFirst=false, node=f44e0815-5711-4b98-8a26-4f9ae6000000]], tx=GridNearTxLocal [mappings=IgniteTxMappingsImpl [], nearLocallyMapped=false, colocatedLocallyMapped=false, needCheckBackup=null, hasRemoteLocks=false, trackTimeout=true, thread=tx-thread-2, mappings=IgniteTxMappingsImpl [], super=GridDhtTxLocalAdapter [nearOnOriginatingNode=false, nearNodes=[], dhtNodes=[], explicitLock=false, super=IgniteTxLocalAdapter [completedBase=null, sndTransformedVals=false, depEnabled=false, txState=IgniteTxStateImpl [activeCacheIds=GridIntList [idx=1, arr=[3556498]], recovery=false, txMap=[IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], val=null, startVer=1509110498766, ver=GridCacheVersion [topVer=120590501, order=1509110498766, nodeOrder=1], hash=1, extras=null, flags=2]], prepared=0, locked=false, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1]], IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], val=null, startVer=1509110498765, ver=GridCacheVersion [topVer=120590501, order=1509110498765, nodeOrder=1], hash=2, extras=null, flags=2]], prepared=0, locked=false, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1]]]], super=IgniteTxAdapter [xidVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], writeVer=null, implicit=false, loc=true, threadId=60, startTime=1509110501490, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, startVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], endVer=null, isolation=READ_COMMITTED, concurrency=OPTIMISTIC, timeout=500, sysInvalidate=false, sys=false, plc=2, commitVer=null, finalizing=NONE, invalidParts=null, state=PREPARING, topVer=AffinityTopologyVersion [topVer=1, minorTopVer=1], duration=121ms, onePhaseCommit=false], size=2]]]]
[615][tx-thread-2][exchange] Rechecking pending locks for completion.
[615][tx-thread-1][exchange] Rechecking pending locks for completion.
[641][tx-thread-2][GridCacheMvcc] Adding local candidate [mvcc=GridCacheMvcc [locs=null, rmts=null], parent=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], val=null, startVer=1509110498765, ver=GridCacheVersion [topVer=120590501, order=1509110498765, nodeOrder=1], hash=2, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=null, rmts=null]], flags=2]], threadId=60, ver=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], timeout=359, reenter=false, tx=true]
[641][tx-thread-1][GridCacheMvcc] Adding local candidate [mvcc=GridCacheMvcc [locs=null, rmts=null], parent=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], val=null, startVer=1509110498766, ver=GridCacheVersion [topVer=120590501, order=1509110498766, nodeOrder=1], hash=1, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=null, rmts=null]], flags=2]], threadId=59, ver=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], timeout=359, reenter=false, tx=true]
[646][tx-thread-1][GridCacheMvccManager] Linked new candidate: GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], threadId=59, id=2, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=0|ready=0|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=null]
[647][tx-thread-2][GridCacheMvccManager] Linked new candidate: GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], threadId=60, id=1, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=0|ready=0|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=null]
[647][tx-thread-1][GridCacheMvccManager] Received owner changed callback [KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], owner=GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], threadId=59, id=2, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=null]]
[647][tx-thread-2][GridCacheMvccManager] Received owner changed callback [KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], owner=GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], threadId=60, id=1, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=null]]
[647][tx-thread-1][GridNearTxPrepareFutureAdapter] Transaction future received owner changed callback: GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], val=null, startVer=1509110498766, ver=GridCacheVersion [topVer=120590501, order=1509110498766, nodeOrder=1], hash=1, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], threadId=59, id=2, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=null]], rmts=null]], flags=2]]
[648][tx-thread-2][GridNearTxPrepareFutureAdapter] Transaction future received owner changed callback: GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], val=null, startVer=1509110498765, ver=GridCacheVersion [topVer=120590501, order=1509110498765, nodeOrder=1], hash=2, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], threadId=60, id=1, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=null]], rmts=null]], flags=2]]
[648][tx-thread-1][GridNearTxPrepareFutureAdapter] Still waiting for locks [fut=KeyLockFuture [lockKeys=GridConcurrentHashSet [elements=[IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498]]], allKeysAdded=true, super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=1188433266]], keys=GridConcurrentHashSet [elements=[IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498]]]]
[649][tx-thread-2][GridNearTxPrepareFutureAdapter] Still waiting for locks [fut=KeyLockFuture [lockKeys=GridConcurrentHashSet [elements=[IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498]]], allKeysAdded=true, super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=355191933]], keys=GridConcurrentHashSet [elements=[IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498]]]]
[649][tx-thread-2][MemoryEventStorageSpi] Event recorded: CacheEvent [cacheName=test, part=0, key=2, xid=cc5cefd5f51-00000000-0730-10a5-0000-000000000001, lockId=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], newVal=null, oldVal=null, hasOldVal=false, hasNewVal=false, near=false, subjId=null, cloClsName=null, taskName=null, nodeId8=f44e0815, evtNodeId8=f44e0815, msg=Cache event., type=CACHE_OBJECT_LOCKED, tstamp=1509110501641]
[649][tx-thread-1][MemoryEventStorageSpi] Event recorded: CacheEvent [cacheName=test, part=0, key=1, xid=bc5cefd5f51-00000000-0730-10a5-0000-000000000001, lockId=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], newVal=null, oldVal=null, hasOldVal=false, hasNewVal=false, near=false, subjId=null, cloClsName=null, taskName=null, nodeId8=f44e0815, evtNodeId8=f44e0815, msg=Cache event., type=CACHE_OBJECT_LOCKED, tstamp=1509110501641]
[650][tx-thread-2][GridCacheMvcc] Adding local candidate [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], threadId=59, id=2, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=null]], rmts=null], parent=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], val=null, startVer=1509110498766, ver=GridCacheVersion [topVer=120590501, order=1509110498766, nodeOrder=1], hash=1, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], threadId=59, id=2, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=null]], rmts=null]], flags=2]], threadId=60, ver=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], timeout=359, reenter=false, tx=true]
[651][tx-thread-1][GridCacheMvcc] Adding local candidate [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], threadId=60, id=1, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=null]], rmts=null], parent=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], val=null, startVer=1509110498765, ver=GridCacheVersion [topVer=120590501, order=1509110498765, nodeOrder=1], hash=2, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], threadId=60, id=1, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=null]], rmts=null]], flags=2]], threadId=59, ver=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], timeout=359, reenter=false, tx=true]
[651][tx-thread-2][GridCacheMvccManager] Linked new candidate: GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], threadId=60, id=3, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=0|ready=0|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], nextVer=null]
[651][tx-thread-1][GridCacheMvccManager] Linked new candidate: GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], threadId=59, id=4, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=0|ready=0|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], nextVer=null]
[653][tx-thread-2][GridCacheMvccManager] Added future to future map: GridDhtTxPrepareFuture [futId=623cefd5f51-8fb787fc-5e22-4c80-b23c-fc65177bb643, err=null, replied=0, mapped=0, req=null, trackable=true, nearMiniId=0, last=true, retVal=false, ret=null, lockKeys=[], forceKeysFut=null, locksReady=false, invoke=false, timeoutObj=PrepareTimeoutObject [timeout=369], xid=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], innerFuts=[], super=GridCompoundFuture [rdc=org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtTxPrepareFuture$1@3b04eeb1, initFlag=0, lsnrCalls=0, done=false, cancelled=false, err=null, futs=[]]]
[653][tx-thread-1][GridCacheMvccManager] Added future to future map: GridDhtTxPrepareFuture [futId=723cefd5f51-8fb787fc-5e22-4c80-b23c-fc65177bb643, err=null, replied=0, mapped=0, req=null, trackable=true, nearMiniId=0, last=true, retVal=false, ret=null, lockKeys=[], forceKeysFut=null, locksReady=false, invoke=false, timeoutObj=PrepareTimeoutObject [timeout=369], xid=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], innerFuts=[], super=GridCompoundFuture [rdc=org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtTxPrepareFuture$1@3b04eeb1, initFlag=0, lsnrCalls=0, done=false, cancelled=false, err=null, futs=[]]]
[666][tx-thread-1][GridDhtTxPrepareFuture] Marking all local candidates as ready: GridDhtTxPrepareFuture [futId=723cefd5f51-8fb787fc-5e22-4c80-b23c-fc65177bb643, err=null, replied=0, mapped=0, req=GridNearTxPrepareRequest [futId=523cefd5f51-8fb787fc-5e22-4c80-b23c-fc65177bb643, miniId=1, topVer=AffinityTopologyVersion [topVer=1, minorTopVer=1], subjId=f44e0815-5711-4b98-8a26-4f9ae6000000, taskNameHash=0, flags=, super=GridDistributedTxPrepareRequest [threadId=59, concurrency=OPTIMISTIC, isolation=READ_COMMITTED, writeVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], timeout=379, reads=null, writes=[IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], val=null, startVer=1509110498766, ver=GridCacheVersion [topVer=120590501, order=1509110498766, nodeOrder=1], hash=1, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], threadId=59, id=2, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1]], GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], threadId=60, id=3, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], nextVer=null]], rmts=null]], flags=2]], prepared=1, locked=false, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1]], IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], val=null, startVer=1509110498765, ver=GridCacheVersion [topVer=120590501, order=1509110498765, nodeOrder=1], hash=2, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], threadId=60, id=1, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1]], GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], threadId=59, id=4, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], nextVer=null]], rmts=null]], flags=2]], prepared=1, locked=false, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1]]], dhtVers=null, txSize=0, plc=2, txState=IgniteTxStateImpl [activeCacheIds=GridIntList [idx=1, arr=[3556498]], recovery=false, txMap=[IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], val=null, startVer=1509110498765, ver=GridCacheVersion [topVer=120590501, order=1509110498765, nodeOrder=1], hash=2, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], threadId=60, id=1, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1]], GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], threadId=59, id=4, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], nextVer=null]], rmts=null]], flags=2]], prepared=1, locked=false, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1]], IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], val=null, startVer=1509110498766, ver=GridCacheVersion [topVer=120590501, order=1509110498766, nodeOrder=1], hash=1, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], threadId=59, id=2, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1]], GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], threadId=60, id=3, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], nextVer=null]], rmts=null]], flags=2]], prepared=1, locked=false, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1]]]],
flags=onePhase|last, super=GridDistributedBaseMessage [ver=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], committedVers=null, rolledbackVers=null, cnt=0, super=GridCacheIdMessage [cacheId=0]]]], trackable=true, nearMiniId=0, last=true, retVal=false, ret=null, lockKeys=[], forceKeysFut=null, locksReady=false, invoke=false, timeoutObj=PrepareTimeoutObject [timeout=369], xid=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], innerFuts=[], super=GridCompoundFuture [rdc=org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtTxPrepareFuture$1@3b04eeb1, initFlag=0, lsnrCalls=0, done=false, cancelled=false, err=null, futs=[]]]
[666][tx-thread-2][GridDhtTxPrepareFuture] Marking all local candidates as ready: GridDhtTxPrepareFuture [futId=623cefd5f51-8fb787fc-5e22-4c80-b23c-fc65177bb643, err=null, replied=0, mapped=0, req=GridNearTxPrepareRequest [futId=423cefd5f51-8fb787fc-5e22-4c80-b23c-fc65177bb643, miniId=1, topVer=AffinityTopologyVersion [topVer=1, minorTopVer=1], subjId=f44e0815-5711-4b98-8a26-4f9ae6000000, taskNameHash=0, flags=, super=GridDistributedTxPrepareRequest [threadId=60, concurrency=OPTIMISTIC, isolation=READ_COMMITTED, writeVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], timeout=379, reads=null, writes=[IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], val=null, startVer=1509110498765, ver=GridCacheVersion [topVer=120590501, order=1509110498765, nodeOrder=1], hash=2, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], threadId=60, id=1, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1]], GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], threadId=59, id=4, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], nextVer=null]], rmts=null]], flags=2]], prepared=1, locked=false, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1]], IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], val=null, startVer=1509110498766, ver=GridCacheVersion [topVer=120590501, order=1509110498766, nodeOrder=1], hash=1, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], threadId=59, id=2, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1]], GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], threadId=60, id=3, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], nextVer=null]], rmts=null]], flags=2]], prepared=1, locked=false, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1]]], dhtVers=null, txSize=0, plc=2, txState=IgniteTxStateImpl [activeCacheIds=GridIntList [idx=1, arr=[3556498]], recovery=false, txMap=[IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], val=null, startVer=1509110498766, ver=GridCacheVersion [topVer=120590501, order=1509110498766, nodeOrder=1], hash=1, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], threadId=59, id=2, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1]], GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], threadId=60, id=3, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], nextVer=null]], rmts=null]], flags=2]], prepared=1, locked=false, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1]], IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], val=null, startVer=1509110498765, ver=GridCacheVersion [topVer=120590501, order=1509110498765, nodeOrder=1], hash=2, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], threadId=60, id=1, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1]], GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], threadId=59, id=4, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], nextVer=null]], rmts=null]], flags=2]], prepared=1, locked=false, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1]]]],
flags=onePhase|last, super=GridDistributedBaseMessage [ver=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], committedVers=null, rolledbackVers=null, cnt=0, super=GridCacheIdMessage [cacheId=0]]]], trackable=true, nearMiniId=0, last=true, retVal=false, ret=null, lockKeys=[], forceKeysFut=null, locksReady=false, invoke=false, timeoutObj=PrepareTimeoutObject [timeout=369], xid=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], innerFuts=[], super=GridCompoundFuture [rdc=org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtTxPrepareFuture$1@3b04eeb1, initFlag=0, lsnrCalls=0, done=false, cancelled=false, err=null, futs=[]]]
[673][tx-thread-1][GridNearTxLocal] Changed transaction state [prev=PREPARING, new=PREPARED, tx=GridNearTxLocal [mappings=IgniteTxMappingsImpl [], nearLocallyMapped=false, colocatedLocallyMapped=false, needCheckBackup=null, hasRemoteLocks=false, trackTimeout=true, thread=tx-thread-1, mappings=IgniteTxMappingsImpl [], super=GridDhtTxLocalAdapter [nearOnOriginatingNode=false, nearNodes=[], dhtNodes=[], explicitLock=false, super=IgniteTxLocalAdapter [completedBase=null, sndTransformedVals=false, depEnabled=false, txState=IgniteTxStateImpl [activeCacheIds=GridIntList [idx=1, arr=[3556498]], recovery=false, txMap=[IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], val=null, startVer=1509110498765, ver=GridCacheVersion [topVer=120590501, order=1509110498765, nodeOrder=1], hash=2, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], threadId=60, id=1, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1]], GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], threadId=59, id=4, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], nextVer=null]], rmts=null]], flags=2]], prepared=1, locked=false, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1]], IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], val=null, startVer=1509110498766, ver=GridCacheVersion [topVer=120590501, order=1509110498766, nodeOrder=1], hash=1, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], threadId=59, id=2, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1]], GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], threadId=60, id=3, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], nextVer=null]], rmts=null]], flags=2]], prepared=1, locked=false, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1]]]], super=IgniteTxAdapter [xidVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], writeVer=GridCacheVersion [topVer=120590501, order=1509110498767, nodeOrder=1], implicit=false, loc=true, threadId=59, startTime=1509110501490, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, startVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], endVer=null, isolation=READ_COMMITTED, concurrency=OPTIMISTIC, timeout=500, sysInvalidate=false, sys=false, plc=2, commitVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], finalizing=NONE, invalidParts=null, state=PREPARED, topVer=AffinityTopologyVersion [topVer=1, minorTopVer=1], duration=181ms, onePhaseCommit=true], size=2]]]]
[674][tx-thread-2][GridNearTxLocal] Changed transaction state [prev=PREPARING, new=PREPARED, tx=GridNearTxLocal [mappings=IgniteTxMappingsImpl [], nearLocallyMapped=false, colocatedLocallyMapped=false, needCheckBackup=null, hasRemoteLocks=false, trackTimeout=true, thread=tx-thread-2, mappings=IgniteTxMappingsImpl [], super=GridDhtTxLocalAdapter [nearOnOriginatingNode=false, nearNodes=[], dhtNodes=[], explicitLock=false, super=IgniteTxLocalAdapter [completedBase=null, sndTransformedVals=false, depEnabled=false, txState=IgniteTxStateImpl [activeCacheIds=GridIntList [idx=1, arr=[3556498]], recovery=false, txMap=[IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], val=null, startVer=1509110498766, ver=GridCacheVersion [topVer=120590501, order=1509110498766, nodeOrder=1], hash=1, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], threadId=59, id=2, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1]], GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], threadId=60, id=3, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], nextVer=null]], rmts=null]], flags=2]], prepared=1, locked=false, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1]], IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], val=null, startVer=1509110498765, ver=GridCacheVersion [topVer=120590501, order=1509110498765, nodeOrder=1], hash=2, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], threadId=60, id=1, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1]], GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], threadId=59, id=4, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], nextVer=null]], rmts=null]], flags=2]], prepared=1, locked=false, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1]]]], super=IgniteTxAdapter [xidVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], writeVer=GridCacheVersion [topVer=120590501, order=1509110498768, nodeOrder=1], implicit=false, loc=true, threadId=60, startTime=1509110501490, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, startVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], endVer=null, isolation=READ_COMMITTED, concurrency=OPTIMISTIC, timeout=500, sysInvalidate=false, sys=false, plc=2, commitVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], finalizing=NONE, invalidParts=null, state=PREPARED, topVer=AffinityTopologyVersion [topVer=1, minorTopVer=1], duration=181ms, onePhaseCommit=true], size=2]]]]
[682][tx-thread-1][GridCacheMvccManager] Removed future from future map: GridDhtTxPrepareFuture [futId=723cefd5f51-8fb787fc-5e22-4c80-b23c-fc65177bb643, err=null, replied=1, mapped=1, req=GridNearTxPrepareRequest [futId=523cefd5f51-8fb787fc-5e22-4c80-b23c-fc65177bb643, miniId=1, topVer=AffinityTopologyVersion [topVer=1, minorTopVer=1], subjId=f44e0815-5711-4b98-8a26-4f9ae6000000, taskNameHash=0, flags=, super=GridDistributedTxPrepareRequest [threadId=59, concurrency=OPTIMISTIC, isolation=READ_COMMITTED, writeVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], timeout=379, reads=null, writes=[IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], val=null, startVer=1509110498766, ver=GridCacheVersion [topVer=120590501, order=1509110498766, nodeOrder=1], hash=1, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], threadId=59, id=2, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1]], GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], threadId=60, id=3, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], nextVer=null]], rmts=null]], flags=2]], prepared=1, locked=false, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1]], IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], val=null, startVer=1509110498765, ver=GridCacheVersion [topVer=120590501, order=1509110498765, nodeOrder=1], hash=2, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], threadId=60, id=1, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1]], GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], threadId=59, id=4, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], nextVer=null]], rmts=null]], flags=2]], prepared=1, locked=false, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1]]], dhtVers=null, txSize=0, plc=2, txState=IgniteTxStateImpl [activeCacheIds=GridIntList [idx=1, arr=[3556498]], recovery=false, txMap=[IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], val=null, startVer=1509110498765, ver=GridCacheVersion [topVer=120590501, order=1509110498765, nodeOrder=1], hash=2, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], threadId=60, id=1, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1]], GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], threadId=59, id=4, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], nextVer=null]], rmts=null]], flags=2]], prepared=1, locked=false, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1]], IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], val=null, startVer=1509110498766, ver=GridCacheVersion [topVer=120590501, order=1509110498766, nodeOrder=1], hash=1, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], threadId=59, id=2, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1]], GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], threadId=60, id=3, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], nextVer=null]], rmts=null]], flags=2]], prepared=1, locked=false, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1]]]],
flags=onePhase|last, super=GridDistributedBaseMessage [ver=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], committedVers=null, rolledbackVers=null, cnt=0, super=GridCacheIdMessage [cacheId=0]]]], trackable=true, nearMiniId=0, last=true, retVal=false, ret=GridCacheReturn [v=null, cacheObj=null, success=true, invokeRes=false, loc=true, cacheId=0], lockKeys=[], forceKeysFut=null, locksReady=true, invoke=false, timeoutObj=PrepareTimeoutObject [timeout=369], xid=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], innerFuts=[], super=GridCompoundFuture [rdc=org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtTxPrepareFuture$1@3b04eeb1, initFlag=1, lsnrCalls=0, done=true, cancelled=false, err=null, futs=[]]]
[682][tx-thread-2][GridCacheMvccManager] Removed future from future map: GridDhtTxPrepareFuture [futId=623cefd5f51-8fb787fc-5e22-4c80-b23c-fc65177bb643, err=null, replied=1, mapped=1, req=GridNearTxPrepareRequest [futId=423cefd5f51-8fb787fc-5e22-4c80-b23c-fc65177bb643, miniId=1, topVer=AffinityTopologyVersion [topVer=1, minorTopVer=1], subjId=f44e0815-5711-4b98-8a26-4f9ae6000000, taskNameHash=0, flags=, super=GridDistributedTxPrepareRequest [threadId=60, concurrency=OPTIMISTIC, isolation=READ_COMMITTED, writeVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], timeout=379, reads=null, writes=[IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], val=null, startVer=1509110498765, ver=GridCacheVersion [topVer=120590501, order=1509110498765, nodeOrder=1], hash=2, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], threadId=60, id=1, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1]], GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], threadId=59, id=4, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], nextVer=null]], rmts=null]], flags=2]], prepared=1, locked=false, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1]], IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], val=null, startVer=1509110498766, ver=GridCacheVersion [topVer=120590501, order=1509110498766, nodeOrder=1], hash=1, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], threadId=59, id=2, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1]], GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], threadId=60, id=3, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], nextVer=null]], rmts=null]], flags=2]], prepared=1, locked=false, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1]]], dhtVers=null, txSize=0, plc=2, txState=IgniteTxStateImpl [activeCacheIds=GridIntList [idx=1, arr=[3556498]], recovery=false, txMap=[IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], val=null, startVer=1509110498766, ver=GridCacheVersion [topVer=120590501, order=1509110498766, nodeOrder=1], hash=1, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], threadId=59, id=2, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1]], GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], threadId=60, id=3, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], nextVer=null]], rmts=null]], flags=2]], prepared=1, locked=false, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1]], IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], val=null, startVer=1509110498765, ver=GridCacheVersion [topVer=120590501, order=1509110498765, nodeOrder=1], hash=2, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], threadId=60, id=1, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1]], GridCacheMvccCandidate [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], threadId=59, id=4, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120590501, order=1509110498763, nodeOrder=1], nextVer=null]], rmts=null]], flags=2]], prepared=1, locked=false, nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1]]]],
flags=onePhase|last, super=GridDistributedBaseMessage [ver=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], committedVers=null, rolledbackVers=null, cnt=0, super=GridCacheIdMessage [cacheId=0]]]], trackable=true, nearMiniId=0, last=true, retVal=false, ret=GridCacheReturn [v=null, cacheObj=null, success=true, invokeRes=false, loc=true, cacheId=0], lockKeys=[], forceKeysFut=null, locksReady=true, invoke=false, timeoutObj=PrepareTimeoutObject [timeout=369], xid=GridCacheVersion [topVer=120590501, order=1509110498764, nodeOrder=1], innerFuts=[], super=GridCompoundFuture [rdc=org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtTxPrepareFuture$1@3b04eeb1, initFlag=1, lsnrCalls=0, done=true, cancelled=false, err=null, futs=[]]]
[689][tx-thread-2][GridCacheVersionManager] Did not update version from node (version has lower order) [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=1509110498764, curOrder=1509110498768]
[689][tx-thread-1][GridCacheVersionManager] Did not update version from node (version has lower order) [nodeId=f44e0815-5711-4b98-8a26-4f9ae6000000, ver=1509110498763, curOrder=1509110498768]
{noformat}
Seems that timeout didn’t happen because GridDhtTxPrepareFuture is completed successfully with cleaning up timeout handlers. At the same time, GridNearOptimisticTxPrepareFuture cannot be completed because of KeyLockFuture.
Typical diagnostic messages:
{noformat}
Found long running transaction [startTime=15:36:29.058, curTime=15:36:48.924, tx=GridNearTxLocal [mappings=IgniteTxMappingsImpl [], nearLocallyMapped=false, colocatedLocallyMapped=false, needCheckBackup=null, hasRemoteLocks=false, trackTimeout=true, thread=tx-thread-2, mappings=IgniteTxMappingsImpl [], super=GridDhtTxLocalAdapter [nearOnOriginatingNode=false, nearNodes=[], dhtNodes=[], explicitLock=false, super=IgniteTxLocalAdapter [completedBase=null, sndTransformedVals=false, depEnabled=false, txState=IgniteTxStateImpl [activeCacheIds=GridIntList [idx=1, arr=[3556498]], recovery=false, txMap=[IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], val=null, startVer=1509107786434, ver=GridCacheVersion [topVer=120587789, order=1509107786434, nodeOrder=1], hash=2, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, ver=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1], threadId=60, id=1, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1]], GridCacheMvccCandidate [nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, ver=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1], threadId=59, id=4, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1], nextVer=null]], rmts=null]], flags=2]], prepared=1, locked=false, nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1]], IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], val=null, startVer=1509107786435, ver=GridCacheVersion [topVer=120587789, order=1509107786435, nodeOrder=1], hash=1, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, ver=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1], threadId=59, id=2, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1]], GridCacheMvccCandidate [nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, ver=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1], threadId=60, id=3, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1], nextVer=null]], rmts=null]], flags=2]], prepared=1, locked=false, nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1]]]], super=IgniteTxAdapter [xidVer=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1], writeVer=GridCacheVersion [topVer=120587789, order=1509107786437, nodeOrder=1], implicit=false, loc=true, threadId=60, startTime=1509107789058, nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, startVer=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1], endVer=null, isolation=REPEATABLE_READ, concurrency=OPTIMISTIC, timeout=500, sysInvalidate=false, sys=false, plc=2, commitVer=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1], finalizing=NONE, invalidParts=null, state=PREPARED, topVer=AffinityTopologyVersion [topVer=1, minorTopVer=1], duration=19866ms, onePhaseCommit=true], size=2]]]]
Found long running transaction [startTime=15:36:29.058, curTime=15:36:48.924, tx=GridNearTxLocal [mappings=IgniteTxMappingsImpl [], nearLocallyMapped=false, colocatedLocallyMapped=false, needCheckBackup=null, hasRemoteLocks=false, trackTimeout=true, thread=tx-thread-1, mappings=IgniteTxMappingsImpl [], super=GridDhtTxLocalAdapter [nearOnOriginatingNode=false, nearNodes=[], dhtNodes=[], explicitLock=false, super=IgniteTxLocalAdapter [completedBase=null, sndTransformedVals=false, depEnabled=false, txState=IgniteTxStateImpl [activeCacheIds=GridIntList [idx=1, arr=[3556498]], recovery=false, txMap=[IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], val=null, startVer=1509107786434, ver=GridCacheVersion [topVer=120587789, order=1509107786434, nodeOrder=1], hash=2, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, ver=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1], threadId=60, id=1, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1]], GridCacheMvccCandidate [nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, ver=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1], threadId=59, id=4, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1], nextVer=null]], rmts=null]], flags=2]], prepared=1, locked=false, nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1]], IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], val=null, startVer=1509107786435, ver=GridCacheVersion [topVer=120587789, order=1509107786435, nodeOrder=1], hash=1, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, ver=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1], threadId=59, id=2, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1]], GridCacheMvccCandidate [nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, ver=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1], threadId=60, id=3, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1], nextVer=null]], rmts=null]], flags=2]], prepared=1, locked=false, nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1]]]], super=IgniteTxAdapter [xidVer=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1], writeVer=GridCacheVersion [topVer=120587789, order=1509107786436, nodeOrder=1], implicit=false, loc=true, threadId=59, startTime=1509107789058, nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, startVer=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1], endVer=null, isolation=REPEATABLE_READ, concurrency=OPTIMISTIC, timeout=500, sysInvalidate=false, sys=false, plc=2, commitVer=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1], finalizing=NONE, invalidParts=null, state=PREPARED, topVer=AffinityTopologyVersion [topVer=1, minorTopVer=1], duration=19876ms, onePhaseCommit=true], size=2]]]]
Found long running cache future [startTime=15:36:29.108, curTime=15:36:48.924, fut=GridNearOptimisticTxPrepareFuture [miniId=1, txMapping=o.a.i.i.processors.cache.distributed.dht.GridDhtTxMapping@3a8d0470, innerFuts=[[node=617e8ad1-f6aa-4fd3-a382-82bb5b500000, loc=true, done=true]], keyLockFut=KeyLockFuture [lockKeys=GridConcurrentHashSet [elements=[IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498]]], allKeysAdded=true, super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=1995544]], tx=GridNearTxLocal [mappings=IgniteTxMappingsImpl [], nearLocallyMapped=false, colocatedLocallyMapped=false, needCheckBackup=null, hasRemoteLocks=false, trackTimeout=true, thread=tx-thread-2, mappings=IgniteTxMappingsImpl [], super=GridDhtTxLocalAdapter [nearOnOriginatingNode=false, nearNodes=[], dhtNodes=[], explicitLock=false, super=IgniteTxLocalAdapter [completedBase=null, sndTransformedVals=false, depEnabled=false, txState=IgniteTxStateImpl [activeCacheIds=GridIntList [idx=1, arr=[3556498]], recovery=false, txMap=[IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], val=null, startVer=1509107786434, ver=GridCacheVersion [topVer=120587789, order=1509107786434, nodeOrder=1], hash=2, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, ver=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1], threadId=60, id=1, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1]], GridCacheMvccCandidate [nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, ver=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1], threadId=59, id=4, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1], nextVer=null]], rmts=null]], flags=2]], prepared=1, locked=false, nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1]], IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], val=null, startVer=1509107786435, ver=GridCacheVersion [topVer=120587789, order=1509107786435, nodeOrder=1], hash=1, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, ver=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1], threadId=59, id=2, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1]], GridCacheMvccCandidate [nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, ver=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1], threadId=60, id=3, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1], nextVer=null]], rmts=null]], flags=2]], prepared=1, locked=false, nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1]]]], super=IgniteTxAdapter [xidVer=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1], writeVer=GridCacheVersion [topVer=120587789, order=1509107786437, nodeOrder=1], implicit=false, loc=true, threadId=60, startTime=1509107789058, nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, startVer=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1], endVer=null, isolation=REPEATABLE_READ, concurrency=OPTIMISTIC, timeout=500, sysInvalidate=false, sys=false, plc=2, commitVer=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1], finalizing=NONE, invalidParts=null, state=PREPARED, topVer=AffinityTopologyVersion [topVer=1, minorTopVer=1], duration=19906ms, onePhaseCommit=true], size=2]]], super=GridCompoundFuture [rdc=o.a.i.i.processors.cache.distributed.near.GridNearTxPrepareFutureAdapter$1@275ad01a, initFlag=1, lsnrCalls=1, done=false, cancelled=false, err=null, futs=[false, true]]]]
Found long running cache future [startTime=15:36:29.108, curTime=15:36:48.924, fut=GridNearOptimisticTxPrepareFuture [miniId=1, txMapping=o.a.i.i.processors.cache.distributed.dht.GridDhtTxMapping@4269f928, innerFuts=[[node=617e8ad1-f6aa-4fd3-a382-82bb5b500000, loc=true, done=true]], keyLockFut=KeyLockFuture [lockKeys=GridConcurrentHashSet [elements=[IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498]]], allKeysAdded=true, super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=996463400]], tx=GridNearTxLocal [mappings=IgniteTxMappingsImpl [], nearLocallyMapped=false, colocatedLocallyMapped=false, needCheckBackup=null, hasRemoteLocks=false, trackTimeout=true, thread=tx-thread-1, mappings=IgniteTxMappingsImpl [], super=GridDhtTxLocalAdapter [nearOnOriginatingNode=false, nearNodes=[], dhtNodes=[], explicitLock=false, super=IgniteTxLocalAdapter [completedBase=null, sndTransformedVals=false, depEnabled=false, txState=IgniteTxStateImpl [activeCacheIds=GridIntList [idx=1, arr=[3556498]], recovery=false, txMap=[IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], val=null, startVer=1509107786434, ver=GridCacheVersion [topVer=120587789, order=1509107786434, nodeOrder=1], hash=2, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, ver=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1], threadId=60, id=1, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1]], GridCacheMvccCandidate [nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, ver=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1], threadId=59, id=4, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1], nextVer=null]], rmts=null]], flags=2]], prepared=1, locked=false, nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1]], IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], val=null, startVer=1509107786435, ver=GridCacheVersion [topVer=120587789, order=1509107786435, nodeOrder=1], hash=1, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, ver=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1], threadId=59, id=2, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1]], GridCacheMvccCandidate [nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, ver=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1], threadId=60, id=3, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1], nextVer=null]], rmts=null]], flags=2]], prepared=1, locked=false, nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1]]]], super=IgniteTxAdapter [xidVer=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1], writeVer=GridCacheVersion [topVer=120587789, order=1509107786436, nodeOrder=1], implicit=false, loc=true, threadId=59, startTime=1509107789058, nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, startVer=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1], endVer=null, isolation=REPEATABLE_READ, concurrency=OPTIMISTIC, timeout=500, sysInvalidate=false, sys=false, plc=2, commitVer=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1], finalizing=NONE, invalidParts=null, state=PREPARED, topVer=AffinityTopologyVersion [topVer=1, minorTopVer=1], duration=19906ms, onePhaseCommit=true], size=2]]], super=GridCompoundFuture [rdc=o.a.i.i.processors.cache.distributed.near.GridNearTxPrepareFutureAdapter$1@275ad01a, initFlag=1, lsnrCalls=1, done=false, cancelled=false, err=null, futs=[false, true]]]]
Found long running cache future [startTime=15:36:29.108, curTime=15:36:48.924, fut=GridNearTxFinishFuture [futId=28065dd5f51-fb37df1b-c2fa-42c1-a3fe-77de2d35be22, tx=GridNearTxLocal [mappings=IgniteTxMappingsImpl [], nearLocallyMapped=false, colocatedLocallyMapped=false, needCheckBackup=null, hasRemoteLocks=false, trackTimeout=true, thread=tx-thread-1, mappings=IgniteTxMappingsImpl [], super=GridDhtTxLocalAdapter [nearOnOriginatingNode=false, nearNodes=[], dhtNodes=[], explicitLock=false, super=IgniteTxLocalAdapter [completedBase=null, sndTransformedVals=false, depEnabled=false, txState=IgniteTxStateImpl [activeCacheIds=GridIntList [idx=1, arr=[3556498]], recovery=false, txMap=[IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], val=null, startVer=1509107786434, ver=GridCacheVersion [topVer=120587789, order=1509107786434, nodeOrder=1], hash=2, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, ver=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1], threadId=60, id=1, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1]], GridCacheMvccCandidate [nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, ver=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1], threadId=59, id=4, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1], nextVer=null]], rmts=null]], flags=2]], prepared=1, locked=false, nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1]], IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], val=null, startVer=1509107786435, ver=GridCacheVersion [topVer=120587789, order=1509107786435, nodeOrder=1], hash=1, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, ver=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1], threadId=59, id=2, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1]], GridCacheMvccCandidate [nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, ver=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1], threadId=60, id=3, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1], nextVer=null]], rmts=null]], flags=2]], prepared=1, locked=false, nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1]]]], super=IgniteTxAdapter [xidVer=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1], writeVer=GridCacheVersion [topVer=120587789, order=1509107786436, nodeOrder=1], implicit=false, loc=true, threadId=59, startTime=1509107789058, nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, startVer=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1], endVer=null, isolation=REPEATABLE_READ, concurrency=OPTIMISTIC, timeout=500, sysInvalidate=false, sys=false, plc=2, commitVer=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1], finalizing=NONE, invalidParts=null, state=PREPARED, topVer=AffinityTopologyVersion [topVer=1, minorTopVer=1], duration=19916ms, onePhaseCommit=true], size=2]]], commit=true, mappings=IgniteTxMappingsImpl [], trackable=true, finishOnePhaseCalled=false, innerFuts=[], super=GridCompoundIdentityFuture [super=GridCompoundFuture [rdc=AlwaysTrueReducer [], initFlag=0, lsnrCalls=0, done=false, cancelled=false, err=null, futs=[]]]]]
Found long running cache future [startTime=15:36:29.108, curTime=15:36:48.924, fut=GridNearTxFinishFuture [futId=38065dd5f51-fb37df1b-c2fa-42c1-a3fe-77de2d35be22, tx=GridNearTxLocal [mappings=IgniteTxMappingsImpl [], nearLocallyMapped=false, colocatedLocallyMapped=false, needCheckBackup=null, hasRemoteLocks=false, trackTimeout=true, thread=tx-thread-2, mappings=IgniteTxMappingsImpl [], super=GridDhtTxLocalAdapter [nearOnOriginatingNode=false, nearNodes=[], dhtNodes=[], explicitLock=false, super=IgniteTxLocalAdapter [completedBase=null, sndTransformedVals=false, depEnabled=false, txState=IgniteTxStateImpl [activeCacheIds=GridIntList [idx=1, arr=[3556498]], recovery=false, txMap=[IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], val=null, startVer=1509107786434, ver=GridCacheVersion [topVer=120587789, order=1509107786434, nodeOrder=1], hash=2, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, ver=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1], threadId=60, id=1, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1]], GridCacheMvccCandidate [nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, ver=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1], threadId=59, id=4, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=2, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1], nextVer=null]], rmts=null]], flags=2]], prepared=1, locked=false, nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1]], IgniteTxEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498, txKey=IgniteTxKey [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], cacheId=3556498], val=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], prevVal=[op=CREATE, val=UserCacheObjectImpl [val=0, hasValBytes=false]], oldVal=[op=NOOP, val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, filtersSet=true, entry=GridLocalCacheEntry [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], val=null, startVer=1509107786435, ver=GridCacheVersion [topVer=120587789, order=1509107786435, nodeOrder=1], hash=1, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc [locs=[GridCacheMvccCandidate [nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, ver=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1], threadId=59, id=2, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=null, nextVer=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1]], GridCacheMvccCandidate [nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, ver=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1], threadId=60, id=3, topVer=AffinityTopologyVersion [topVer=-1, minorTopVer=0], reentry=null, otherNodeId=null, otherVer=null, mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, serOrder=null, key=KeyCacheObjectImpl [part=0, val=1, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=0|near_local=0|removed=0|read=0, prevVer=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1], nextVer=null]], rmts=null]], flags=2]], prepared=1, locked=false, nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1]]]], super=IgniteTxAdapter [xidVer=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1], writeVer=GridCacheVersion [topVer=120587789, order=1509107786437, nodeOrder=1], implicit=false, loc=true, threadId=60, startTime=1509107789058, nodeId=617e8ad1-f6aa-4fd3-a382-82bb5b500000, startVer=GridCacheVersion [topVer=120587789, order=1509107786433, nodeOrder=1], endVer=null, isolation=REPEATABLE_READ, concurrency=OPTIMISTIC, timeout=500, sysInvalidate=false, sys=false, plc=2, commitVer=GridCacheVersion [topVer=120587789, order=1509107786432, nodeOrder=1], finalizing=NONE, invalidParts=null, state=PREPARED, topVer=AffinityTopologyVersion [topVer=1, minorTopVer=1], duration=19926ms, onePhaseCommit=true], size=2]]], commit=true, mappings=IgniteTxMappingsImpl [], trackable=true, finishOnePhaseCalled=false, innerFuts=[], super=GridCompoundIdentityFuture [super=GridCompoundFuture [rdc=AlwaysTrueReducer [], initFlag=0, lsnrCalls=0, done=false, cancelled=false, err=null, futs=[]]]]]
{noformat}
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)